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/06/25 02:36:26 UTC

[JENKINS] Lucene-Solr-Tests-4.x-Java7 - Build # 1355 - Still Failing

Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java7/1355/

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

Error Message:
Server at http://127.0.0.1:16149/b_/a 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:16149/b_/a returned non ok status:500, message:Server Error
	at __randomizedtesting.SeedInfo.seed([18B01DA2375BEBA0:995693BA40048B9C]: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:228)
	at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:150)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
	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 9651 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4]   2> 807251 T2278 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /b_/a
[junit4:junit4]   2> 807257 T2278 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./solrtest-ShardSplitTest-1372119294422
[junit4:junit4]   2> 807259 T2278 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 807260 T2279 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 807361 T2278 oasc.ZkTestServer.run start zk server on port:51689
[junit4:junit4]   2> 807362 T2278 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 807366 T2285 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@67b8259f name:ZooKeeperConnection Watcher:127.0.0.1:51689 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 807367 T2278 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 807367 T2278 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 807388 T2278 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 807395 T2287 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@486b4581 name:ZooKeeperConnection Watcher:127.0.0.1:51689/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 807395 T2278 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 807396 T2278 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 807409 T2278 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 807413 T2278 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 807416 T2278 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 807424 T2278 oasc.AbstractZkTestCase.putConfig 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]   2> 807425 T2278 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 807439 T2278 oasc.AbstractZkTestCase.putConfig 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]   2> 807440 T2278 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 807544 T2278 oasc.AbstractZkTestCase.putConfig 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]   2> 807545 T2278 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 807549 T2278 oasc.AbstractZkTestCase.putConfig 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]   2> 807549 T2278 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 807553 T2278 oasc.AbstractZkTestCase.putConfig 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]   2> 807554 T2278 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 807557 T2278 oasc.AbstractZkTestCase.putConfig 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]   2> 807558 T2278 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 807561 T2278 oasc.AbstractZkTestCase.putConfig 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]   2> 807562 T2278 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 807565 T2278 oasc.AbstractZkTestCase.putConfig 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]   2> 807566 T2278 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 807571 T2278 oasc.AbstractZkTestCase.putConfig 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]   2> 807571 T2278 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 807846 T2278 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 807851 T2278 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:20355
[junit4:junit4]   2> 807852 T2278 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 807853 T2278 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 807853 T2278 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372119294740
[junit4:junit4]   2> 807854 T2278 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372119294740/solr.xml
[junit4:junit4]   2> 807854 T2278 oasc.CoreContainer.<init> New CoreContainer 1819587397
[junit4:junit4]   2> 807855 T2278 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372119294740/'
[junit4:junit4]   2> 807856 T2278 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372119294740/'
[junit4:junit4]   2> 807988 T2278 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 807989 T2278 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 807990 T2278 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 807990 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 807991 T2278 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 807992 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 807992 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 807993 T2278 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 807993 T2278 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 807994 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 808012 T2278 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 808013 T2278 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51689/solr
[junit4:junit4]   2> 808013 T2278 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 808015 T2278 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 808018 T2298 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@41ff41b0 name:ZooKeeperConnection Watcher:127.0.0.1:51689 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 808018 T2278 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 808021 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 808034 T2278 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 808036 T2300 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1911a82c name:ZooKeeperConnection Watcher:127.0.0.1:51689/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 808036 T2278 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 808039 T2278 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 808048 T2278 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 808052 T2278 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 808059 T2278 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:20355_b_%2Fa
[junit4:junit4]   2> 808061 T2278 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:20355_b_%2Fa
[junit4:junit4]   2> 808065 T2278 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 808084 T2278 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 808086 T2278 oasc.Overseer.start Overseer (id=89923210079764483-127.0.0.1:20355_b_%2Fa-n_0000000000) starting
[junit4:junit4]   2> 808099 T2278 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 808110 T2302 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 808111 T2278 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 808114 T2278 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 808116 T2278 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 808119 T2301 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 808123 T2303 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 808123 T2303 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 809623 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 809623 T2301 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:20355_b_%2Fa",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:20355/b_/a"}
[junit4:junit4]   2> 809624 T2301 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 809624 T2301 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 809641 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 810127 T2303 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372119294740/collection1
[junit4:junit4]   2> 810127 T2303 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 810128 T2303 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 810129 T2303 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 810130 T2303 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372119294740/collection1/'
[junit4:junit4]   2> 810132 T2303 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1372119294740/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 810132 T2303 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1372119294740/collection1/lib/README' to classloader
[junit4:junit4]   2> 810187 T2303 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 810248 T2303 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 810350 T2303 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 810356 T2303 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 810948 T2303 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 810952 T2303 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 810955 T2303 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 810960 T2303 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 810985 T2303 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 810986 T2303 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372119294740/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372119294422/control/data/
[junit4:junit4]   2> 810986 T2303 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5b48760d
[junit4:junit4]   2> 810987 T2303 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 810987 T2303 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372119294422/control/data
[junit4:junit4]   2> 810988 T2303 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372119294422/control/data/index/
[junit4:junit4]   2> 810988 T2303 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372119294422/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 810989 T2303 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372119294422/control/data/index
[junit4:junit4]   2> 810993 T2303 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5edd33d4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c8d65ed),segFN=segments_1,generation=1}
[junit4:junit4]   2> 810994 T2303 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 810997 T2303 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 810997 T2303 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 810998 T2303 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 810999 T2303 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 811000 T2303 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 811000 T2303 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 811000 T2303 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 811001 T2303 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 811001 T2303 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 811018 T2303 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 811025 T2303 oass.SolrIndexSearcher.<init> Opening Searcher@1a4bbc8b main
[junit4:junit4]   2> 811026 T2303 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372119294422/control/data/tlog
[junit4:junit4]   2> 811027 T2303 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 811027 T2303 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 811031 T2304 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1a4bbc8b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 811033 T2303 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 811033 T2303 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:20355/b_/a collection:control_collection shard:shard1
[junit4:junit4]   2> 811034 T2303 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 811076 T2303 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 811088 T2303 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 811088 T2303 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 811089 T2303 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:20355/b_/a/collection1/
[junit4:junit4]   2> 811089 T2303 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 811089 T2303 oasc.SyncStrategy.syncToMe http://127.0.0.1:20355/b_/a/collection1/ has no replicas
[junit4:junit4]   2> 811089 T2303 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:20355/b_/a/collection1/
[junit4:junit4]   2> 811090 T2303 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 811145 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 811163 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 811208 T2303 oasc.ZkController.register We are http://127.0.0.1:20355/b_/a/collection1/ and leader is http://127.0.0.1:20355/b_/a/collection1/
[junit4:junit4]   2> 811208 T2303 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:20355/b_/a
[junit4:junit4]   2> 811208 T2303 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 811209 T2303 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 811209 T2303 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 811211 T2303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 811212 T2278 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4]   2> 811213 T2278 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 811213 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 811231 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 811233 T2278 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 811235 T2307 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5705b8fd name:ZooKeeperConnection Watcher:127.0.0.1:51689/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 811235 T2278 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 811238 T2278 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 811241 T2278 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 811503 T2278 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 811506 T2278 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:16149
[junit4:junit4]   2> 811507 T2278 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 811508 T2278 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 811508 T2278 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372119298405
[junit4:junit4]   2> 811509 T2278 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372119298405/solr.xml
[junit4:junit4]   2> 811509 T2278 oasc.CoreContainer.<init> New CoreContainer 55415664
[junit4:junit4]   2> 811510 T2278 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372119298405/'
[junit4:junit4]   2> 811510 T2278 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372119298405/'
[junit4:junit4]   2> 811641 T2278 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 811642 T2278 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 811642 T2278 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 811643 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 811643 T2278 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 811644 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 811644 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 811645 T2278 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 811646 T2278 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 811646 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 811663 T2278 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 811664 T2278 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51689/solr
[junit4:junit4]   2> 811665 T2278 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 811666 T2278 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 811669 T2318 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15247264 name:ZooKeeperConnection Watcher:127.0.0.1:51689 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 811670 T2278 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 811683 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 811696 T2278 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 811698 T2320 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2af3a6ed name:ZooKeeperConnection Watcher:127.0.0.1:51689/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 811698 T2278 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 811710 T2278 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 812676 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 812677 T2301 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:20355_b_%2Fa_collection1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:20355_b_%2Fa",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:20355/b_/a"}
[junit4:junit4]   2> 812693 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 812693 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 812693 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 812714 T2278 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:16149_b_%2Fa
[junit4:junit4]   2> 812716 T2278 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:16149_b_%2Fa
[junit4:junit4]   2> 812719 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 812719 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 812719 T2307 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 812719 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 812720 T2300 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 812721 T2320 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 812733 T2321 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 812733 T2321 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 814200 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 814201 T2301 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:16149_b_%2Fa",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:16149/b_/a"}
[junit4:junit4]   2> 814201 T2301 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 814201 T2301 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 814221 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 814221 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 814221 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 814737 T2321 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372119298405/collection1
[junit4:junit4]   2> 814737 T2321 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 814738 T2321 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 814739 T2321 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 814740 T2321 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372119298405/collection1/'
[junit4:junit4]   2> 814742 T2321 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1372119298405/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 814742 T2321 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1372119298405/collection1/lib/README' to classloader
[junit4:junit4]   2> 814797 T2321 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 814859 T2321 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 814961 T2321 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 814967 T2321 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 815551 T2321 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 815555 T2321 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 815557 T2321 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 815563 T2321 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 815588 T2321 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 815589 T2321 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372119298405/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty1/
[junit4:junit4]   2> 815589 T2321 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5b48760d
[junit4:junit4]   2> 815590 T2321 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 815590 T2321 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty1
[junit4:junit4]   2> 815591 T2321 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty1/index/
[junit4:junit4]   2> 815591 T2321 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 815592 T2321 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty1/index
[junit4:junit4]   2> 815596 T2321 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2906b081 lockFactory=org.apache.lucene.store.NativeFSLockFactory@70792cb0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 815596 T2321 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 815600 T2321 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 815600 T2321 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 815601 T2321 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 815602 T2321 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 815603 T2321 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 815603 T2321 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 815603 T2321 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 815604 T2321 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 815605 T2321 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 815621 T2321 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 815628 T2321 oass.SolrIndexSearcher.<init> Opening Searcher@50d2b948 main
[junit4:junit4]   2> 815629 T2321 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty1/tlog
[junit4:junit4]   2> 815630 T2321 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 815630 T2321 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 815635 T2322 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@50d2b948 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 815637 T2321 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 815638 T2321 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:16149/b_/a collection:collection1 shard:shard1
[junit4:junit4]   2> 815639 T2321 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 815686 T2321 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 815697 T2321 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 815698 T2321 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 815698 T2321 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:16149/b_/a/collection1/
[junit4:junit4]   2> 815698 T2321 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 815698 T2321 oasc.SyncStrategy.syncToMe http://127.0.0.1:16149/b_/a/collection1/ has no replicas
[junit4:junit4]   2> 815699 T2321 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:16149/b_/a/collection1/
[junit4:junit4]   2> 815699 T2321 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 815725 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 815734 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 815734 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 815734 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 815765 T2321 oasc.ZkController.register We are http://127.0.0.1:16149/b_/a/collection1/ and leader is http://127.0.0.1:16149/b_/a/collection1/
[junit4:junit4]   2> 815765 T2321 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:16149/b_/a
[junit4:junit4]   2> 815765 T2321 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 815766 T2321 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 815766 T2321 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 815769 T2321 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 815770 T2278 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4]   2> 815771 T2278 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 815771 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 816060 T2278 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 816063 T2278 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:46017
[junit4:junit4]   2> 816064 T2278 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 816064 T2278 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 816065 T2278 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372119302953
[junit4:junit4]   2> 816066 T2278 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372119302953/solr.xml
[junit4:junit4]   2> 816066 T2278 oasc.CoreContainer.<init> New CoreContainer 1111199469
[junit4:junit4]   2> 816067 T2278 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372119302953/'
[junit4:junit4]   2> 816067 T2278 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372119302953/'
[junit4:junit4]   2> 816222 T2278 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 816223 T2278 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 816224 T2278 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 816224 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 816225 T2278 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 816225 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 816226 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 816227 T2278 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 816227 T2278 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 816228 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 816244 T2278 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 816245 T2278 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51689/solr
[junit4:junit4]   2> 816245 T2278 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 816246 T2278 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 816250 T2334 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4c7f4ae0 name:ZooKeeperConnection Watcher:127.0.0.1:51689 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 816250 T2278 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 816253 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 816264 T2278 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 816266 T2336 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@692c2e7 name:ZooKeeperConnection Watcher:127.0.0.1:51689/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 816267 T2278 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 816279 T2278 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 817240 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 817241 T2301 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:16149_b_%2Fa_collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:16149_b_%2Fa",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:16149/b_/a"}
[junit4:junit4]   2> 817257 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 817258 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 817258 T2336 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 817258 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 817282 T2278 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46017_b_%2Fa
[junit4:junit4]   2> 817284 T2278 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46017_b_%2Fa
[junit4:junit4]   2> 817287 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 817287 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 817287 T2336 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 817287 T2307 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 817288 T2336 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 817288 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 817289 T2300 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 817289 T2320 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 817301 T2337 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 817301 T2337 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 818763 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 818765 T2301 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:46017_b_%2Fa",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:46017/b_/a"}
[junit4:junit4]   2> 818765 T2301 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 818765 T2301 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4]   2> 818785 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 818785 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 818785 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 818785 T2336 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 819305 T2337 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372119302953/collection1
[junit4:junit4]   2> 819305 T2337 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 819306 T2337 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 819306 T2337 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 819308 T2337 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372119302953/collection1/'
[junit4:junit4]   2> 819310 T2337 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1372119302953/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 819310 T2337 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1372119302953/collection1/lib/README' to classloader
[junit4:junit4]   2> 819364 T2337 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 819426 T2337 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 819527 T2337 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 819533 T2337 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 820122 T2337 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 820126 T2337 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 820129 T2337 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 820134 T2337 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 820160 T2337 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 820160 T2337 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372119302953/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty2/
[junit4:junit4]   2> 820160 T2337 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5b48760d
[junit4:junit4]   2> 820161 T2337 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 820162 T2337 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty2
[junit4:junit4]   2> 820162 T2337 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty2/index/
[junit4:junit4]   2> 820163 T2337 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 820163 T2337 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty2/index
[junit4:junit4]   2> 820167 T2337 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73fbcfb7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7376508a),segFN=segments_1,generation=1}
[junit4:junit4]   2> 820168 T2337 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 820171 T2337 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 820172 T2337 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 820172 T2337 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 820173 T2337 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 820174 T2337 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 820174 T2337 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 820175 T2337 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 820175 T2337 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 820176 T2337 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 820192 T2337 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 820200 T2337 oass.SolrIndexSearcher.<init> Opening Searcher@541e01d3 main
[junit4:junit4]   2> 820200 T2337 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty2/tlog
[junit4:junit4]   2> 820201 T2337 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 820202 T2337 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 820207 T2338 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@541e01d3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 820209 T2337 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 820210 T2337 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46017/b_/a collection:collection1 shard:shard2
[junit4:junit4]   2> 820211 T2337 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 820231 T2337 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 820240 T2337 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 820240 T2337 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 820241 T2337 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:46017/b_/a/collection1/
[junit4:junit4]   2> 820241 T2337 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 820241 T2337 oasc.SyncStrategy.syncToMe http://127.0.0.1:46017/b_/a/collection1/ has no replicas
[junit4:junit4]   2> 820242 T2337 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:46017/b_/a/collection1/
[junit4:junit4]   2> 820242 T2337 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 820290 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 820306 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 820306 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 820306 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 820306 T2336 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 820357 T2337 oasc.ZkController.register We are http://127.0.0.1:46017/b_/a/collection1/ and leader is http://127.0.0.1:46017/b_/a/collection1/
[junit4:junit4]   2> 820357 T2337 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46017/b_/a
[junit4:junit4]   2> 820357 T2337 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 820358 T2337 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 820358 T2337 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 820360 T2337 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 820361 T2278 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4]   2> 820362 T2278 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 820363 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 820645 T2278 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 820648 T2278 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:25389
[junit4:junit4]   2> 820649 T2278 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 820650 T2278 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 820650 T2278 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372119307544
[junit4:junit4]   2> 820651 T2278 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372119307544/solr.xml
[junit4:junit4]   2> 820651 T2278 oasc.CoreContainer.<init> New CoreContainer 569783213
[junit4:junit4]   2> 820652 T2278 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372119307544/'
[junit4:junit4]   2> 820652 T2278 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372119307544/'
[junit4:junit4]   2> 820783 T2278 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 820784 T2278 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 820784 T2278 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 820785 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 820786 T2278 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 820786 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 820787 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 820787 T2278 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 820788 T2278 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 820788 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 820806 T2278 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 820807 T2278 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51689/solr
[junit4:junit4]   2> 820807 T2278 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 820809 T2278 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 820813 T2350 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4dd94c61 name:ZooKeeperConnection Watcher:127.0.0.1:51689 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 820813 T2278 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 820830 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 820843 T2278 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 820845 T2352 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5dc96818 name:ZooKeeperConnection Watcher:127.0.0.1:51689/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 820846 T2278 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 820857 T2278 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 821820 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 821821 T2301 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:46017_b_%2Fa_collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:46017_b_%2Fa",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:46017/b_/a"}
[junit4:junit4]   2> 821841 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 821841 T2336 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 821841 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 821841 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 821841 T2352 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 821861 T2278 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:25389_b_%2Fa
[junit4:junit4]   2> 821863 T2278 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:25389_b_%2Fa
[junit4:junit4]   2> 821866 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 821866 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 821866 T2336 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 821866 T2352 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 821867 T2336 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 821866 T2307 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 821867 T2352 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 821868 T2300 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 821867 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 821868 T2320 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 821880 T2353 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 821880 T2353 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 823347 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 823347 T2301 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:25389_b_%2Fa",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:25389/b_/a"}
[junit4:junit4]   2> 823348 T2301 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 823348 T2301 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 823364 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 823364 T2336 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 823364 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 823364 T2352 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 823364 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 823884 T2353 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372119307544/collection1
[junit4:junit4]   2> 823884 T2353 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 823885 T2353 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 823885 T2353 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 823887 T2353 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372119307544/collection1/'
[junit4:junit4]   2> 823889 T2353 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1372119307544/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 823889 T2353 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1372119307544/collection1/lib/README' to classloader
[junit4:junit4]   2> 823944 T2353 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 824005 T2353 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 824106 T2353 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 824112 T2353 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 824700 T2353 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 824704 T2353 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 824706 T2353 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 824712 T2353 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 824737 T2353 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 824738 T2353 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372119307544/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty3/
[junit4:junit4]   2> 824738 T2353 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5b48760d
[junit4:junit4]   2> 824739 T2353 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 824740 T2353 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty3
[junit4:junit4]   2> 824740 T2353 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty3/index/
[junit4:junit4]   2> 824740 T2353 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 824742 T2353 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty3/index
[junit4:junit4]   2> 824746 T2353 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6c2bd313 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7747c623),segFN=segments_1,generation=1}
[junit4:junit4]   2> 824746 T2353 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 824750 T2353 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 824750 T2353 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 824751 T2353 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 824752 T2353 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 824752 T2353 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 824753 T2353 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 824753 T2353 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 824754 T2353 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 824754 T2353 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 824771 T2353 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 824779 T2353 oass.SolrIndexSearcher.<init> Opening Searcher@3156a903 main
[junit4:junit4]   2> 824779 T2353 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty3/tlog
[junit4:junit4]   2> 824780 T2353 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 824781 T2353 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 824785 T2354 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3156a903 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 824788 T2353 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 824788 T2353 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:25389/b_/a collection:collection1 shard:shard1
[junit4:junit4]   2> 824792 T2353 oasc.ZkController.register We are http://127.0.0.1:25389/b_/a/collection1/ and leader is http://127.0.0.1:16149/b_/a/collection1/
[junit4:junit4]   2> 824792 T2353 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:25389/b_/a
[junit4:junit4]   2> 824792 T2353 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 824792 T2353 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C513 name=collection1 org.apache.solr.core.SolrCore@6bf2c166 url=http://127.0.0.1:25389/b_/a/collection1 node=127.0.0.1:25389_b_%2Fa C513_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:25389_b_%2Fa, base_url=http://127.0.0.1:25389/b_/a}
[junit4:junit4]   2> 824793 T2355 C513 P25389 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 824793 T2353 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 824794 T2355 C513 P25389 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 824794 T2355 C513 P25389 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 824794 T2355 C513 P25389 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 824795 T2278 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4]   2> 824796 T2278 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 824796 T2355 C513 P25389 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 824796 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 824818 T2310 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:25389_b_%2Fa_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 824870 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 824871 T2301 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:25389_b_%2Fa_collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:25389_b_%2Fa",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:25389/b_/a"}
[junit4:junit4]   2> 824990 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 824990 T2336 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 824990 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 824990 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 824990 T2352 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 825077 T2278 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 825080 T2278 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:24216
[junit4:junit4]   2> 825081 T2278 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 825081 T2278 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 825082 T2278 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372119311980
[junit4:junit4]   2> 825082 T2278 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372119311980/solr.xml
[junit4:junit4]   2> 825083 T2278 oasc.CoreContainer.<init> New CoreContainer 1133154357
[junit4:junit4]   2> 825084 T2278 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372119311980/'
[junit4:junit4]   2> 825084 T2278 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372119311980/'
[junit4:junit4]   2> 825214 T2278 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 825215 T2278 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 825216 T2278 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 825216 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 825217 T2278 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 825217 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 825218 T2278 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 825219 T2278 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 825219 T2278 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 825220 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 825237 T2278 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 825238 T2278 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51689/solr
[junit4:junit4]   2> 825239 T2278 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 825240 T2278 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 825242 T2367 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@74d15d70 name:ZooKeeperConnection Watcher:127.0.0.1:51689 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 825244 T2278 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 825246 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 825259 T2278 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 825261 T2369 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6b0d311e name:ZooKeeperConnection Watcher:127.0.0.1:51689/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 825262 T2278 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 825274 T2278 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 825819 T2310 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:25389_b_%2Fa_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4]   2> 825819 T2310 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:25389_b_%252Fa_collection1&state=recovering&nodeName=127.0.0.1:25389_b_%252Fa&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001 
[junit4:junit4]   2> 826278 T2278 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:24216_b_%2Fa
[junit4:junit4]   2> 826283 T2278 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:24216_b_%2Fa
[junit4:junit4]   2> 826286 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 826287 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 826287 T2336 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 826287 T2369 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 826287 T2336 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 826287 T2307 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 826287 T2352 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 826288 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 826289 T2320 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 826289 T2300 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 826288 T2352 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 826303 T2370 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 826304 T2370 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 826494 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 826495 T2301 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:24216_b_%2Fa",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:24216/b_/a"}
[junit4:junit4]   2> 826495 T2301 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 826496 T2301 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4]   2> 826513 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 826513 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 826513 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 826513 T2369 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 826513 T2336 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 826513 T2352 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 827306 T2370 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372119311980/collection1
[junit4:junit4]   2> 827306 T2370 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 827307 T2370 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 827307 T2370 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 827309 T2370 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372119311980/collection1/'
[junit4:junit4]   2> 827310 T2370 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1372119311980/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 827311 T2370 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1372119311980/collection1/lib/README' to classloader
[junit4:junit4]   2> 827366 T2370 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 827450 T2370 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 827551 T2370 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 827557 T2370 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> ASYNC  NEW_CORE C514 name=collection1 org.apache.solr.core.SolrCore@6bf2c166 url=http://127.0.0.1:25389/b_/a/collection1 node=127.0.0.1:25389_b_%2Fa C514_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:25389_b_%2Fa, base_url=http://127.0.0.1:25389/b_/a}
[junit4:junit4]   2> 827821 T2355 C514 P25389 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:16149/b_/a/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 827821 T2355 C514 P25389 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:25389/b_/a START replicas=[http://127.0.0.1:16149/b_/a/collection1/] nUpdates=100
[junit4:junit4]   2> 827822 T2355 C514 P25389 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 827823 T2355 C514 P25389 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 827823 T2355 C514 P25389 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 827823 T2355 C514 P25389 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 827824 T2355 C514 P25389 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 827824 T2355 C514 P25389 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:16149/b_/a/collection1/. core=collection1
[junit4:junit4]   2> 827824 T2355 C514 P25389 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C515 name=collection1 org.apache.solr.core.SolrCore@18dd9cc8 url=http://127.0.0.1:16149/b_/a/collection1 node=127.0.0.1:16149_b_%2Fa C515_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:16149_b_%2Fa, base_url=http://127.0.0.1:16149/b_/a, leader=true}
[junit4:junit4]   2> 827831 T2311 C515 P16149 oasc.SolrCore.execute [collection1] webapp=/b_/a path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> 827836 T2312 C515 P16149 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 827839 T2312 C515 P16149 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2906b081 lockFactory=org.apache.lucene.store.NativeFSLockFactory@70792cb0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 827839 T2312 C515 P16149 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 827840 T2312 C515 P16149 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2906b081 lockFactory=org.apache.lucene.store.NativeFSLockFactory@70792cb0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2906b081 lockFactory=org.apache.lucene.store.NativeFSLockFactory@70792cb0),segFN=segments_2,generation=2}
[junit4:junit4]   2> 827841 T2312 C515 P16149 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 827841 T2312 C515 P16149 oass.SolrIndexSearcher.<init> Opening Searcher@35c214eb realtime
[junit4:junit4]   2> 827842 T2312 C515 P16149 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 827842 T2312 C515 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4]   2> 827843 T2355 C514 P25389 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 827844 T2355 C514 P25389 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 827846 T2313 C515 P16149 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 827846 T2313 C515 P16149 oasc.SolrCore.execute [collection1] webapp=/b_/a path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   2> 827847 T2355 C514 P25389 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 827847 T2355 C514 P25389 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 827847 T2355 C514 P25389 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 827850 T2313 C515 P16149 oasc.SolrCore.execute [collection1] webapp=/b_/a path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0 
[junit4:junit4]   2> 827851 T2355 C514 P25389 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 827852 T2355 C514 P25389 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty3/index.20130624191515016
[junit4:junit4]   2> 827852 T2355 C514 P25389 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@97f489b lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fa6c6a4) fullCopy=false
[junit4:junit4]   2> 827855 T2313 C515 P16149 oasc.SolrCore.execute [collection1] webapp=/b_/a path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 827856 T2355 C514 P25389 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 827857 T2355 C514 P25389 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 827858 T2355 C514 P25389 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 827860 T2355 C514 P25389 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6c2bd313 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7747c623),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6c2bd313 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7747c623),segFN=segments_2,generation=2}
[junit4:junit4]   2> 827860 T2355 C514 P25389 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 827861 T2355 C514 P25389 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 827861 T2355 C514 P25389 oass.SolrIndexSearcher.<init> Opening Searcher@7c313551 main
[junit4:junit4]   2> 827862 T2354 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7c313551 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 827863 T2355 C514 P25389 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty3/index.20130624191515016 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty3/index.20130624191515016;done=true>>]
[junit4:junit4]   2> 827863 T2355 C514 P25389 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty3/index.20130624191515016
[junit4:junit4]   2> 827864 T2355 C514 P25389 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty3/index.20130624191515016
[junit4:junit4]   2> 827864 T2355 C514 P25389 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 827864 T2355 C514 P25389 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 827865 T2355 C514 P25389 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 827865 T2355 C514 P25389 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 827867 T2355 C514 P25389 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 828018 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 828019 T2301 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:25389_b_%2Fa_collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:25389_b_%2Fa",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:25389/b_/a"}
[junit4:junit4]   2> 828033 T2352 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 828033 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 828033 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 828033 T2369 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 828033 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 828033 T2336 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 828146 T2370 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 828151 T2370 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 828153 T2370 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 828158 T2370 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 828183 T2370 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 828184 T2370 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372119311980/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4/
[junit4:junit4]   2> 828184 T2370 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5b48760d
[junit4:junit4]   2> 828185 T2370 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 828185 T2370 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4
[junit4:junit4]   2> 828186 T2370 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4/index/
[junit4:junit4]   2> 828186 T2370 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 828187 T2370 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4/index
[junit4:junit4]   2> 828191 T2370 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2e3543fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@502a854c),segFN=segments_1,generation=1}
[junit4:junit4]   2> 828191 T2370 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 828195 T2370 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 828195 T2370 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 828196 T2370 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 828197 T2370 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 828197 T2370 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 828198 T2370 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 828199 T2370 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 828199 T2370 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 828200 T2370 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 828216 T2370 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 828224 T2370 oass.SolrIndexSearcher.<init> Opening Searcher@c28b0f7 main
[junit4:junit4]   2> 828225 T2370 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4/tlog
[junit4:junit4]   2> 828226 T2370 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 828226 T2370 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 828231 T2373 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c28b0f7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 828233 T2370 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 828234 T2370 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:24216/b_/a collection:collection1 shard:shard2
[junit4:junit4]   2> 828237 T2370 oasc.ZkController.register We are http://127.0.0.1:24216/b_/a/collection1/ and leader is http://127.0.0.1:46017/b_/a/collection1/
[junit4:junit4]   2> 828238 T2370 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:24216/b_/a
[junit4:junit4]   2> 828238 T2370 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 828238 T2370 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C516 name=collection1 org.apache.solr.core.SolrCore@fe03b75 url=http://127.0.0.1:24216/b_/a/collection1 node=127.0.0.1:24216_b_%2Fa C516_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:24216_b_%2Fa, base_url=http://127.0.0.1:24216/b_/a}
[junit4:junit4]   2> 828239 T2374 C516 P24216 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 828239 T2370 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 828239 T2374 C516 P24216 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 828240 T2374 C516 P24216 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 828240 T2374 C516 P24216 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 828240 T2278 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4]   2> 828241 T2278 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 828242 T2374 C516 P24216 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 828242 T2278 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 828265 T2278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 828266 T2326 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:24216_b_%2Fa_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 828267 T2278 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4]   2> 828267 T2278 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4]   2> 828268 T2278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 829270 T2278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 829538 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 829539 T2301 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:24216_b_%2Fa_collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:24216_b_%2Fa",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:24216/b_/a"}
[junit4:junit4]   2> 829558 T2336 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 829558 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 829558 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 829558 T2352 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 829558 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 829558 T2369 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 830269 T2326 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:24216_b_%2Fa_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4]   2> 830269 T2326 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:24216_b_%252Fa_collection1&state=recovering&nodeName=127.0.0.1:24216_b_%252Fa&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003 
[junit4:junit4]   2> 830273 T2278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 831275 T2278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C516_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:24216_b_%2Fa, base_url=http://127.0.0.1:24216/b_/a}
[junit4:junit4]   2> 832271 T2374 C516 P24216 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:46017/b_/a/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 832271 T2374 C516 P24216 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:24216/b_/a START replicas=[http://127.0.0.1:46017/b_/a/collection1/] nUpdates=100
[junit4:junit4]   2> 832272 T2374 C516 P24216 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 832272 T2374 C516 P24216 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 832272 T2374 C516 P24216 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 832273 T2374 C516 P24216 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 832273 T2374 C516 P24216 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 832273 T2374 C516 P24216 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:46017/b_/a/collection1/. core=collection1
[junit4:junit4]   2> 832273 T2374 C516 P24216 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 832278 T2278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> ASYNC  NEW_CORE C517 name=collection1 org.apache.solr.core.SolrCore@7341af48 url=http://127.0.0.1:46017/b_/a/collection1 node=127.0.0.1:46017_b_%2Fa C517_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:46017_b_%2Fa, base_url=http://127.0.0.1:46017/b_/a, leader=true}
[junit4:junit4]   2> 832282 T2327 C517 P46017 oasc.SolrCore.execute [collection1] webapp=/b_/a path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=2 
[junit4:junit4]   2> 832288 T2328 C517 P46017 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 832290 T2328 C517 P46017 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73fbcfb7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7376508a),segFN=segments_1,generation=1}
[junit4:junit4]   2> 832291 T2328 C517 P46017 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 832292 T2328 C517 P46017 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73fbcfb7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7376508a),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73fbcfb7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7376508a),segFN=segments_2,generation=2}
[junit4:junit4]   2> 832293 T2328 C517 P46017 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 832293 T2328 C517 P46017 oass.SolrIndexSearcher.<init> Opening Searcher@5852b17d realtime
[junit4:junit4]   2> 832294 T2328 C517 P46017 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 832294 T2328 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4]   2> 832295 T2374 C516 P24216 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 832296 T2374 C516 P24216 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 832297 T2329 C517 P46017 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 832298 T2329 C517 P46017 oasc.SolrCore.execute [collection1] webapp=/b_/a path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   2> 832298 T2374 C516 P24216 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 832298 T2374 C516 P24216 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 832299 T2374 C516 P24216 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 832301 T2329 C517 P46017 oasc.SolrCore.execute [collection1] webapp=/b_/a path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0 
[junit4:junit4]   2> 832302 T2374 C516 P24216 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 832303 T2374 C516 P24216 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4/index.20130624191519466
[junit4:junit4]   2> 832303 T2374 C516 P24216 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@5403ed52 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7fe0c390) fullCopy=false
[junit4:junit4]   2> 832306 T2329 C517 P46017 oasc.SolrCore.execute [collection1] webapp=/b_/a path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 832307 T2374 C516 P24216 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 832308 T2374 C516 P24216 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 832308 T2374 C516 P24216 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 832310 T2374 C516 P24216 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2e3543fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@502a854c),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2e3543fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@502a854c),segFN=segments_2,generation=2}
[junit4:junit4]   2> 832311 T2374 C516 P24216 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 832311 T2374 C516 P24216 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 832311 T2374 C516 P24216 oass.SolrIndexSearcher.<init> Opening Searcher@30e226e2 main
[junit4:junit4]   2> 832313 T2373 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@30e226e2 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 832313 T2374 C516 P24216 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4/index.20130624191519466 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4/index.20130624191519466;done=true>>]
[junit4:junit4]   2> 832314 T2374 C516 P24216 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4/index.20130624191519466
[junit4:junit4]   2> 832314 T2374 C516 P24216 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4/index.20130624191519466
[junit4:junit4]   2> 832314 T2374 C516 P24216 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 832314 T2374 C516 P24216 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 832315 T2374 C516 P24216 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 832315 T2374 C516 P24216 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 832317 T2374 C516 P24216 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 832564 T2301 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 832565 T2301 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:24216_b_%2Fa_collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:24216_b_%2Fa",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:24216/b_/a"}
[junit4:junit4]   2> 832578 T2300 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 832579 T2320 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 832579 T2307 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 832578 T2336 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 832578 T2369 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 832578 T2352 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 833281 T2278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 833283 T2278 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4]   2> ASYNC  NEW_CORE C518 name=collection1 org.apache.solr.core.SolrCore@48215358 url=http://127.0.0.1:20355/b_/a/collection1 node=127.0.0.1:20355_b_%2Fa C518_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:20355_b_%2Fa, base_url=http://127.0.0.1:20355/b_/a, leader=true}
[junit4:junit4]   2> 833291 T2290 C518 P20355 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 833295 T2290 C518 P20355 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5edd33d4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c8d65ed),segFN=segments_1,generation=1}
[junit4:junit4]   2> 833296 T2290 C518 P20355 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 833296 T2290 C518 P20355 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5edd33d4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c8d65ed),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5edd33d4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c8d65ed),segFN=segments_2,generation=2}
[junit4:junit4]   2> 833297 T2290 C518 P20355 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 833298 T2290 C518 P20355 oass.SolrIndexSearcher.<init> Opening Searcher@6f0fef36 main
[junit4:junit4]   2> 833298 T2290 C518 P20355 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 833299 T2304 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6f0fef36 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 833300 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4]   2> 833313 T2330 C517 P46017 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:16149/b_/a/collection1/, StdNode: http://127.0.0.1:25389/b_/a/collection1/, StdNode: http://127.0.0.1:46017/b_/a/collection1/, StdNode: http://127.0.0.1:24216/b_/a/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4]   2> ASYNC  NEW_CORE C519 name=collection1 org.apache.solr.core.SolrCore@18dd9cc8 url=http://127.0.0.1:16149/b_/a/collection1 node=127.0.0.1:16149_b_%2Fa C519_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:16149_b_%2Fa, base_url=http://127.0.0.1:16149/b_/a, leader=true}
[junit4:junit4]   2> 833316 T2314 C519 P16149 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 833316 T2331 C517 P46017 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 833317 T2314 C519 P16149 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2906b081 lockFactory=org.apache.lucene.store.NativeFSLockFactory@70792cb0),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2906b081 lockFactory=org.apache.lucene.store.NativeFSLockFactory@70792cb0),segFN=segments_3,generation=3}
[junit4:junit4]   2> 833317 T2331 C517 P46017 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73fbcfb7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7376508a),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@73fbcfb7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7376508a),segFN=segments_3,generation=3}
[junit4:junit4]   2> 833318 T2314 C519 P16149 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 833318 T2331 C517 P46017 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 833319 T2314 C519 P16149 oass.SolrIndexSearcher.<init> Opening Searcher@6121865a main
[junit4:junit4]   2> 833319 T2331 C517 P46017 oass.SolrIndexSearcher.<init> Opening Searcher@502a04c main
[junit4:junit4]   2> 833320 T2314 C519 P16149 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 833321 T2322 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6121865a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 833320 T2331 C517 P46017 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 833321 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4]   2> 833321 T2338 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@502a04c main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 833323 T2331 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4]   2>  C516_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:24216_b_%2Fa, base_url=http://127.0.0.1:24216/b_/a}
[junit4:junit4]   2> 833324 T2359 C516 P24216 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> ASYNC  NEW_CORE C520 name=collection1 org.apache.solr.core.SolrCore@6bf2c166 url=http://127.0.0.1:25389/b_/a/collection1 node=127.0.0.1:25389_b_%2Fa C520_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:25389_b_%2Fa, base_url=http://127.0.0.1:25389/b_/a}
[junit4:junit4]   2> 833324 T2342 C520 P25389 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 833325 T2359 C516 P24216 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2e3543fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@502a854c),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2e3543fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@502a854c),segFN=segments_3,generation=3}
[junit4:junit4]   2> 833325 T2342 C520 P25389 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6c2bd313 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7747c623),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6c2bd313 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7747c623),segFN=segments_3,generation=3}
[junit4:junit4]   2> 833326 T2359 C516 P24216 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 833326 T2342 C520 P25389 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 833327 T2359 C516 P24216 oass.SolrIndexSearcher.<init> Opening Searcher@7ea9306c main
[junit4:junit4]   2> 833328 T2342 C520 P25389 oass.SolrIndexSearcher.<init> Opening Searcher@6db40cb main
[junit4:junit4]   2> 833328 T2359 C516 P24216 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 833329 T2373 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7ea9306c main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 833328 T2342 C520 P25389 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 833329 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4]   2> 833329 T2354 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6db40cb main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 833331 T2342 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4]   2> 833331 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 18
[junit4:junit4]   2> 833333 T2278 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 833336 T2315 C519 P16149 oasc.SolrCore.execute [collection1] webapp=/b_/a path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1 
[junit4:junit4]   2> 833338 T2343 C520 P25389 oasc.SolrCore.execute [collection1] webapp=/b_/a path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0 
[junit4:junit4]   2> 833340 T2332 C517 P46017 oasc.SolrCore.execute [collection1] webapp=/b_/a path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0 
[junit4:junit4]   2> 833342 T2360 C516 P24216 oasc.SolrCore.execute [collection1] webapp=/b_/a path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1 
[junit4:junit4]   2> 835347 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438771390720245760)} 0 2
[junit4:junit4]   2> 835355 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={update.distrib=FROMLEADER&_version_=-1438771390724440064&update.from=http://127.0.0.1:16149/b_/a/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438771390724440064)} 0 1
[junit4:junit4]   2> 835359 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={update.distrib=FROMLEADER&_version_=-1438771390728634368&update.from=http://127.0.0.1:46017/b_/a/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438771390728634368)} 0 1
[junit4:junit4]   2> 835360 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438771390728634368)} 0 6
[junit4:junit4]   2> 835361 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438771390724440064)} 0 11
[junit4:junit4]   2> 835365 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[a!0 (1438771390739120128)]} 0 1
[junit4:junit4]   2> 835372 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1438771390743314432)]} 0 1
[junit4:junit4]   2> 835372 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[a!0 (1438771390743314432)]} 0 4
[junit4:junit4]   2> 835375 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[b!1 (1438771390750654464)]} 0 0
[junit4:junit4]   2> 835382 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1438771390753800192)]} 0 1
[junit4:junit4]   2> 835382 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[b!1 (1438771390753800192)]} 0 4
[junit4:junit4]   2> 835385 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[c!2 (1438771390761140224)]} 0 0
[junit4:junit4]   2> 835394 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1438771390766383104)]} 0 1
[junit4:junit4]   2> 835394 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!2 (1438771390766383104)]} 0 4
[junit4:junit4]   2> 835395 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[c!2]} 0 7
[junit4:junit4]   2> 835398 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[d!3 (1438771390774771712)]} 0 0
[junit4:junit4]   2> 835404 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1438771390777917440)]} 0 0
[junit4:junit4]   2> 835405 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[d!3 (1438771390777917440)]} 0 4
[junit4:junit4]   2> 835408 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[e!4 (1438771390785257472)]} 0 0
[junit4:junit4]   2> 835415 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1438771390788403200)]} 0 1
[junit4:junit4]   2> 835415 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[e!4 (1438771390788403200)]} 0 4
[junit4:junit4]   2> 835418 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[f!5 (1438771390795743232)]} 0 0
[junit4:junit4]   2> 835426 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1438771390800986112)]} 0 0
[junit4:junit4]   2> 835427 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1438771390800986112)]} 0 4
[junit4:junit4]   2> 835428 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[f!5]} 0 7
[junit4:junit4]   2> 835431 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[g!6 (1438771390809374720)]} 0 0
[junit4:junit4]   2> 835439 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1438771390814617600)]} 0 0
[junit4:junit4]   2> 835440 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!6 (1438771390814617600)]} 0 4
[junit4:junit4]   2> 835441 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[g!6]} 0 7
[junit4:junit4]   2> 835444 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[h!7 (1438771390823006208)]} 0 0
[junit4:junit4]   2> 835453 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1438771390828249088)]} 0 1
[junit4:junit4]   2> 835453 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!7 (1438771390828249088)]} 0 4
[junit4:junit4]   2> 835454 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[h!7]} 0 7
[junit4:junit4]   2> 835457 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[i!8 (1438771390836637696)]} 0 0
[junit4:junit4]   2> 835465 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1438771390841880576)]} 0 0
[junit4:junit4]   2> 835466 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!8 (1438771390841880576)]} 0 4
[junit4:junit4]   2> 835467 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[i!8]} 0 7
[junit4:junit4]   2> 835470 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[j!9 (1438771390850269184)]} 0 0
[junit4:junit4]   2> 835478 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1438771390855512064)]} 0 0
[junit4:junit4]   2> 835479 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!9 (1438771390855512064)]} 0 4
[junit4:junit4]   2> 835480 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[j!9]} 0 7
[junit4:junit4]   2> 835484 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[k!10 (1438771390863900672)]} 0 1
[junit4:junit4]   2> 835489 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1438771390867046400)]} 0 0
[junit4:junit4]   2> 835490 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[k!10 (1438771390867046400)]} 0 4
[junit4:junit4]   2> 835493 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[l!11 (1438771390874386432)]} 0 0
[junit4:junit4]   2> 835499 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1438771390877532160)]} 0 0
[junit4:junit4]   2> 835500 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[l!11 (1438771390877532160)]} 0 4
[junit4:junit4]   2> 835503 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[m!12 (1438771390884872192)]} 0 0
[junit4:junit4]   2> 835510 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1438771390888017920)]} 0 0
[junit4:junit4]   2> 835510 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[m!12 (1438771390888017920)]} 0 4
[junit4:junit4]   2> 835513 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[n!13 (1438771390895357952)]} 0 0
[junit4:junit4]   2> 835520 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1438771390898503680)]} 0 1
[junit4:junit4]   2> 835520 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[n!13 (1438771390898503680)]} 0 4
[junit4:junit4]   2> 835523 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[o!14 (1438771390905843712)]} 0 0
[junit4:junit4]   2> 835531 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1438771390911086592)]} 0 0
[junit4:junit4]   2> 835532 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!14 (1438771390911086592)]} 0 4
[junit4:junit4]   2> 835533 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[o!14]} 0 7
[junit4:junit4]   2> 835535 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[p!15 (1438771390918426624)]} 0 0
[junit4:junit4]   2> 835542 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1438771390921572352)]} 0 1
[junit4:junit4]   2> 835542 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[p!15 (1438771390921572352)]} 0 4
[junit4:junit4]   2> 835545 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[q!16 (1438771390928912384)]} 0 0
[junit4:junit4]   2> 835553 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1438771390934155264)]} 0 0
[junit4:junit4]   2> 835554 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1438771390934155264)]} 0 4
[junit4:junit4]   2> 835555 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[q!16]} 0 7
[junit4:junit4]   2> 835558 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[r!17 (1438771390942543872)]} 0 0
[junit4:junit4]   2> 835564 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1438771390945689600)]} 0 0
[junit4:junit4]   2> 835565 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[r!17 (1438771390945689600)]} 0 4
[junit4:junit4]   2> 835568 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[s!18 (1438771390953029632)]} 0 0
[junit4:junit4]   2> 835574 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1438771390956175360)]} 0 0
[junit4:junit4]   2> 835575 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[s!18 (1438771390956175360)]} 0 4
[junit4:junit4]   2> 835578 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[t!19 (1438771390963515392)]} 0 0
[junit4:junit4]   2> 835586 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1438771390968758272)]} 0 0
[junit4:junit4]   2> 835587 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!19 (1438771390968758272)]} 0 4
[junit4:junit4]   2> 835588 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[t!19]} 0 7
[junit4:junit4]   2> 835591 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[u!20 (1438771390976098304)]} 0 1
[junit4:junit4]   2> 835596 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1438771390979244032)]} 0 0
[junit4:junit4]   2> 835597 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[u!20 (1438771390979244032)]} 0 4
[junit4:junit4]   2> 835600 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[v!21 (1438771390986584064)]} 0 0
[junit4:junit4]   2> 835607 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1438771390989729792)]} 0 1
[junit4:junit4]   2> 835607 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[v!21 (1438771390989729792)]} 0 4
[junit4:junit4]   2> 835610 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[w!22 (1438771390997069824)]} 0 0
[junit4:junit4]   2> 835618 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1438771391002312704)]} 0 0
[junit4:junit4]   2> 835619 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!22 (1438771391002312704)]} 0 4
[junit4:junit4]   2> 835620 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[w!22]} 0 7
[junit4:junit4]   2> 835623 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[x!23 (1438771391010701312)]} 0 0
[junit4:junit4]   2> 835631 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1438771391015944192)]} 0 0
[junit4:junit4]   2> 835632 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!23 (1438771391015944192)]} 0 4
[junit4:junit4]   2> 835633 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[x!23]} 0 7
[junit4:junit4]   2> 835637 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[y!24 (1438771391024332800)]} 0 1
[junit4:junit4]   2> 835643 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1438771391028527104)]} 0 0
[junit4:junit4]   2> 835644 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[y!24 (1438771391028527104)]} 0 4
[junit4:junit4]   2> 835647 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[z!25 (1438771391035867136)]} 0 0
[junit4:junit4]   2> 835656 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1438771391041110016)]} 0 1
[junit4:junit4]   2> 835656 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!25 (1438771391041110016)]} 0 4
[junit4:junit4]   2> 835657 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[z!25]} 0 7
[junit4:junit4]   2> 835660 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[a!26 (1438771391049498624)]} 0 0
[junit4:junit4]   2> 835669 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1438771391054741504)]} 0 0
[junit4:junit4]   2> 835669 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!26 (1438771391054741504)]} 0 4
[junit4:junit4]   2> 835670 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[a!26]} 0 7
[junit4:junit4]   2> 835673 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[b!27 (1438771391063130112)]} 0 0
[junit4:junit4]   2> 835681 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1438771391068372992)]} 0 0
[junit4:junit4]   2> 835682 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!27 (1438771391068372992)]} 0 4
[junit4:junit4]   2> 835683 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[b!27]} 0 7
[junit4:junit4]   2> 835686 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[c!28 (1438771391076761600)]} 0 0
[junit4:junit4]   2> 835692 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1438771391079907328)]} 0 0
[junit4:junit4]   2> 835693 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[c!28 (1438771391079907328)]} 0 4
[junit4:junit4]   2> 835696 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[d!29 (1438771391087247360)]} 0 0
[junit4:junit4]   2> 835705 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1438771391092490240)]} 0 1
[junit4:junit4]   2> 835705 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1438771391092490240)]} 0 4
[junit4:junit4]   2> 835706 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[d!29]} 0 7
[junit4:junit4]   2> 835709 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[e!30 (1438771391100878848)]} 0 0
[junit4:junit4]   2> 835718 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1438771391106121728)]} 0 0
[junit4:junit4]   2> 835718 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!30 (1438771391106121728)]} 0 4
[junit4:junit4]   2> 835719 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[e!30]} 0 7
[junit4:junit4]   2> 835722 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[f!31 (1438771391114510336)]} 0 0
[junit4:junit4]   2> 835728 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1438771391117656064)]} 0 0
[junit4:junit4]   2> 835729 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[f!31 (1438771391117656064)]} 0 4
[junit4:junit4]   2> 835732 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[g!32 (1438771391124996096)]} 0 0
[junit4:junit4]   2> 835740 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1438771391130238976)]} 0 0
[junit4:junit4]   2> 835741 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!32 (1438771391130238976)]} 0 4
[junit4:junit4]   2> 835742 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[g!32]} 0 7
[junit4:junit4]   2> 835745 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[h!33 (1438771391138627584)]} 0 0
[junit4:junit4]   2> 835751 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1438771391141773312)]} 0 0
[junit4:junit4]   2> 835752 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[h!33 (1438771391141773312)]} 0 4
[junit4:junit4]   2> 835755 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[i!34 (1438771391149113344)]} 0 0
[junit4:junit4]   2> 835764 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1438771391154356224)]} 0 1
[junit4:junit4]   2> 835764 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!34 (1438771391154356224)]} 0 4
[junit4:junit4]   2> 835765 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[i!34]} 0 7
[junit4:junit4]   2> 835768 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[j!35 (1438771391162744832)]} 0 0
[junit4:junit4]   2> 835774 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1438771391165890560)]} 0 0
[junit4:junit4]   2> 835775 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[j!35 (1438771391165890560)]} 0 4
[junit4:junit4]   2> 835779 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[k!36 (1438771391173230592)]} 0 1
[junit4:junit4]   2> 835786 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1438771391178473472)]} 0 0
[junit4:junit4]   2> 835787 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!36 (1438771391178473472)]} 0 4
[junit4:junit4]   2> 835788 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[k!36]} 0 7
[junit4:junit4]   2> 835791 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[l!37 (1438771391186862080)]} 0 0
[junit4:junit4]   2> 835799 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1438771391192104960)]} 0 0
[junit4:junit4]   2> 835800 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1438771391192104960)]} 0 4
[junit4:junit4]   2> 835801 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[l!37]} 0 7
[junit4:junit4]   2> 835805 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[m!38 (1438771391200493568)]} 0 1
[junit4:junit4]   2> 835814 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1438771391206785024)]} 0 1
[junit4:junit4]   2> 835815 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!38 (1438771391206785024)]} 0 5
[junit4:junit4]   2> 835815 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[m!38]} 0 8
[junit4:junit4]   2> 835819 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[n!39 (1438771391215173632)]} 0 1
[junit4:junit4]   2> 835828 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1438771391221465088)]} 0 1
[junit4:junit4]   2> 835828 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!39 (1438771391221465088)]} 0 4
[junit4:junit4]   2> 835829 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[n!39]} 0 7
[junit4:junit4]   2> 835832 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[o!40 (1438771391229853696)]} 0 0
[junit4:junit4]   2> 835841 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1438771391236145152)]} 0 0
[junit4:junit4]   2> 835842 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!40 (1438771391236145152)]} 0 4
[junit4:junit4]   2> 835843 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[o!40]} 0 8
[junit4:junit4]   2> 835846 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[p!41 (1438771391244533760)]} 0 0
[junit4:junit4]   2> 835853 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1438771391247679488)]} 0 0
[junit4:junit4]   2> 835853 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[p!41 (1438771391247679488)]} 0 4
[junit4:junit4]   2> 835857 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[q!42 (1438771391255019520)]} 0 1
[junit4:junit4]   2> 835864 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1438771391260262400)]} 0 0
[junit4:junit4]   2> 835865 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!42 (1438771391260262400)]} 0 4
[junit4:junit4]   2> 835866 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[q!42]} 0 7
[junit4:junit4]   2> 835869 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[r!43 (1438771391268651008)]} 0 0
[junit4:junit4]   2> 835875 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1438771391271796736)]} 0 0
[junit4:junit4]   2> 835876 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[r!43 (1438771391271796736)]} 0 4
[junit4:junit4]   2> 835880 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[s!44 (1438771391279136768)]} 0 1
[junit4:junit4]   2> 835889 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1438771391284379648)]} 0 1
[junit4:junit4]   2> 835889 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!44 (1438771391284379648)]} 0 5
[junit4:junit4]   2> 835890 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[s!44]} 0 8
[junit4:junit4]   2> 835893 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[t!45 (1438771391293816832)]} 0 0
[junit4:junit4]   2> 835899 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1438771391296962560)]} 0 0
[junit4:junit4]   2> 835900 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[t!45 (1438771391296962560)]} 0 4
[junit4:junit4]   2> 835903 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[u!46 (1438771391304302592)]} 0 0
[junit4:junit4]   2> 835910 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1438771391307448320)]} 0 1
[junit4:junit4]   2> 835911 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[u!46 (1438771391307448320)]} 0 5
[junit4:junit4]   2> 835914 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[v!47 (1438771391314788352)]} 0 1
[junit4:junit4]   2> 835920 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1438771391317934080)]} 0 1
[junit4:junit4]   2> 835920 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[v!47 (1438771391317934080)]} 0 4
[junit4:junit4]   2> 835924 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[w!48 (1438771391325274112)]} 0 1
[junit4:junit4]   2> 835932 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1438771391331565568)]} 0 0
[junit4:junit4]   2> 835933 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!48 (1438771391331565568)]} 0 4
[junit4:junit4]   2> 835934 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[w!48]} 0 7
[junit4:junit4]   2> 835938 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[x!49 (1438771391339954176)]} 0 1
[junit4:junit4]   2> 835946 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1438771391345197056)]} 0 1
[junit4:junit4]   2> 835946 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!49 (1438771391345197056)]} 0 4
[junit4:junit4]   2> 835947 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[x!49]} 0 7
[junit4:junit4]   2> 835951 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[y!50 (1438771391353585664)]} 0 0
[junit4:junit4]   2> 835959 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1438771391358828544)]} 0 1
[junit4:junit4]   2> 835959 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!50 (1438771391358828544)]} 0 4
[junit4:junit4]   2> 835960 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[y!50]} 0 7
[junit4:junit4]   2> 835965 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[z!51 (1438771391368265728)]} 0 1
[junit4:junit4]   2> 835970 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1438771391371411456)]} 0 0
[junit4:junit4]   2> 835971 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[z!51 (1438771391371411456)]} 0 4
[junit4:junit4]   2> 835974 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[a!52 (1438771391378751488)]} 0 0
[junit4:junit4]   2> 835981 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1438771391381897216)]} 0 1
[junit4:junit4]   2> 835981 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[a!52 (1438771391381897216)]} 0 4
[junit4:junit4]   2> 835984 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[b!53 (1438771391389237248)]} 0 0
[junit4:junit4]   2> 835991 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1438771391392382976)]} 0 1
[junit4:junit4]   2> 835991 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[b!53 (1438771391392382976)]} 0 4
[junit4:junit4]   2> 835995 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[c!54 (1438771391399723008)]} 0 1
[junit4:junit4]   2> 836003 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1438771391404965888)]} 0 1
[junit4:junit4]   2> 836003 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!54 (1438771391404965888)]} 0 4
[junit4:junit4]   2> 836004 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[c!54]} 0 7
[junit4:junit4]   2> 836007 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[d!55 (1438771391413354496)]} 0 0
[junit4:junit4]   2> 836014 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1438771391416500224)]} 0 1
[junit4:junit4]   2> 836015 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[d!55 (1438771391416500224)]} 0 5
[junit4:junit4]   2> 836019 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[e!56 (1438771391424888832)]} 0 1
[junit4:junit4]   2> 836027 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1438771391430131712)]} 0 1
[junit4:junit4]   2> 836027 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!56 (1438771391430131712)]} 0 4
[junit4:junit4]   2> 836028 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[e!56]} 0 7
[junit4:junit4]   2> 836032 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[f!57 (1438771391438520320)]} 0 1
[junit4:junit4]   2> 836039 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1438771391443763200)]} 0 0
[junit4:junit4]   2> 836040 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!57 (1438771391443763200)]} 0 4
[junit4:junit4]   2> 836041 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[f!57]} 0 7
[junit4:junit4]   2> 836045 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[g!58 (1438771391452151808)]} 0 1
[junit4:junit4]   2> 836054 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1438771391458443264)]} 0 0
[junit4:junit4]   2> 836054 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!58 (1438771391458443264)]} 0 4
[junit4:junit4]   2> 836055 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[g!58]} 0 8
[junit4:junit4]   2> 836059 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[h!59 (1438771391466831872)]} 0 1
[junit4:junit4]   2> 836067 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1438771391472074752)]} 0 1
[junit4:junit4]   2> 836067 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!59 (1438771391472074752)]} 0 4
[junit4:junit4]   2> 836068 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[h!59]} 0 7
[junit4:junit4]   2> 836072 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[i!60 (1438771391480463360)]} 0 1
[junit4:junit4]   2> 836080 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1438771391486754816)]} 0 0
[junit4:junit4]   2> 836081 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!60 (1438771391486754816)]} 0 4
[junit4:junit4]   2> 836082 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[i!60]} 0 7
[junit4:junit4]   2> 836086 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[j!61 (1438771391495143424)]} 0 1
[junit4:junit4]   2> 836092 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1438771391499337728)]} 0 0
[junit4:junit4]   2> 836093 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[j!61 (1438771391499337728)]} 0 4
[junit4:junit4]   2> 836097 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[k!62 (1438771391506677760)]} 0 1
[junit4:junit4]   2> 836106 T2344 C520 P25389 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!62 (1438771391512969216)]} 0 1
[junit4:junit4]   2> 836106 T2314 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!62 (1438771391512969216)]} 0 4
[junit4:junit4]   2> 836107 T2330 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[k!62]} 0 7
[junit4:junit4]   2> 836111 T2290 C518 P20355 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[l!63 (1438771391521357824)]} 0 1
[junit4:junit4]   2> 836119 T2359 C516 P24216 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:46017/b_/a/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!63 (1438771391526600704)]} 0 1
[junit4:junit4]   2> 836120 T2326 C517 P46017 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={distrib.from=http://127.0.0.1:16149/b_/a/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!63 (1438771391526600704)]} 0 5
[junit4:junit4]   2> 836120 T2316 C519 P16149 oasup.LogUpdateProcessor.finish [collection1] webapp=/b_/a path=/update params={wt=javabin&version=2} {add=[l!63]} 0 7
[junit4:junit

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

n
[junit4:junit4]   2> 1029792 T2278 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1029795 T2278 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@fe03b75
[junit4:junit4]   2> 1029802 T2278 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=2,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=829,adds=829,deletesById=407,deletesByQuery=0,errors=0,cumulative_adds=871,cumulative_deletesById=407,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4]   2> 1029804 T2278 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 1029804 T2278 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 1029804 T2278 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2>  C576_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:24216_b_%2Fa, base_url=http://127.0.0.1:24216/b_/a, leader=true}
[junit4:junit4]   2> 1029819 T2278 C576 P24216 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2e3543fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@502a854c),segFN=segments_4,generation=4}
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2e3543fb lockFactory=org.apache.lucene.store.NativeFSLockFactory@502a854c),segFN=segments_5,generation=5}
[junit4:junit4]   2> 1029819 T2278 C576 P24216 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4]   2> 1029823 T2278 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 1029824 T2278 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4]   2> 1029824 T2278 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4/index;done=false>>]
[junit4:junit4]   2> 1029825 T2278 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4/index
[junit4:junit4]   2> 1029825 T2278 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4;done=false>>]
[junit4:junit4]   2> 1029826 T2278 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372119294422/jetty4
[junit4:junit4]   2> 1029827 T2402 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89923210079764492-127.0.0.1:24216_b_%2Fa-n_0000000004) am no longer a leader.
[junit4:junit4]   2> 1029832 T2278 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/b_/a,null}
[junit4:junit4]   2> 1029901 T2278 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4]   2> 1029903 T2278 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:51689 51689
[junit4:junit4]   2> 1030037 T2352 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 1030139 T2352 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 1030140 T2352 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 1030141 T2278 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 20355
[junit4:junit4]   2> !!!! WARNING: best effort to remove /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-1372119294422 FAILED !!!!!
[junit4:junit4]   2> 1030142 T2278 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4]   2> 1030142 T2278 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:51689 51689
[junit4:junit4]   1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=ShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=18B01DA2375BEBA0 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_SV -Dtests.timezone=America/Panama -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR    223s J0 | ShardSplitTest.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:16149/b_/a returned non ok status:500, message:Server Error
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([18B01DA2375BEBA0:995693BA40048B9C]:0)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4]    > 	at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
[junit4:junit4]    > 	at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:150)
[junit4:junit4]    > 	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4]    > 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 1030162 T2278 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 222917 T2277 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4]   2> 1031132 T2369 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 1031132 T2369 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 1031132 T2369 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> NOTE: test params are: codec=FastCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=FAST, chunkSize=236), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=FAST, chunkSize=236)), sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {}, locale=es_SV, timezone=America/Panama
[junit4:junit4]   2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=1,free=178585744,total=330301440
[junit4:junit4]   2> NOTE: All tests run in this JVM: [DistanceFunctionTest, TestFoldingMultitermQuery, TestCopyFieldCollectionResource, TestDefaultSimilarityFactory, HighlighterConfigTest, CachingDirectoryFactoryTest, SpellCheckCollatorTest, TestWriterPerf, JsonLoaderTest, TestCloudManagedSchemaAddField, DOMUtilTest, TestArbitraryIndexDir, PreAnalyzedUpdateProcessorTest, TestDistributedGrouping, HardAutoCommitTest, PathHierarchyTokenizerFactoryTest, TestReplicationHandler, TermVectorComponentTest, TestPluginEnable, FileBasedSpellCheckerTest, TestReload, AutoCommitTest, DateMathParserTest, SpellingQueryConverterTest, StatelessScriptUpdateProcessorFactoryTest, SolrPluginUtilsTest, TestFieldTypeCollectionResource, TestDistributedSearch, TestSolrCoreProperties, DirectSolrSpellCheckerTest, TestSuggestSpellingConverter, TestPostingsSolrHighlighter, TestNumberUtils, HighlighterTest, RequestHandlersTest, SliceStateTest, TestRandomFaceting, TimeZoneUtilsTest, URLClassifyProcessorTest, PreAnalyzedFieldTest, ConvertedLegacyTest, TestComponentsName, CurrencyFieldOpenExchangeTest, TestReloadAndDeleteDocs, ScriptEngineTest, ResponseLogComponentTest, TestSchemaNameResource, SolrRequestParserTest, UpdateRequestProcessorFactoryTest, SuggesterFSTTest, IndexSchemaRuntimeFieldTest, TestCoreContainer, TestSearchPerf, TestPartialUpdateDeduplication, DocumentAnalysisRequestHandlerTest, ZkNodePropsTest, TestSolrXMLSerializer, TestElisionMultitermQuery, TestConfig, SuggesterTest, SliceStateUpdateTest, TestJmxMonitoredMap, TestDFRSimilarityFactory, TestSchemaVersionResource, TestQuerySenderNoQuery, TestWordDelimiterFilterFactory, CoreAdminHandlerTest, TestValueSourceCache, TestDefaultSearchFieldResource, ChaosMonkeyNothingIsSafeTest, ShowFileRequestHandlerTest, TestLazyCores, TestShardHandlerFactory, ChaosMonkeySafeLeaderTest, ShardSplitTest]
[junit4:junit4] Completed on J0 in 223.96s, 1 test, 1 error <<< FAILURES!

[...truncated 459 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:392: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:372: 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:1246: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:890: There were test failures: 298 suites, 1256 tests, 1 error, 13 ignored (7 assumptions)

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