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/24 21:10:46 UTC
[JENKINS] Lucene-Solr-Tests-trunk-Java7 - Build # 4087 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-Java7/4087/
1 tests failed.
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:58534 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:58534 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([B10E51C03F875E75:30E8DFD848D83E49]: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 9262 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 175982 T524 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 175990 T524 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./solrtest-ShardSplitTest-1372099419798
[junit4:junit4] 2> 175992 T524 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 175993 T525 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 176094 T524 oasc.ZkTestServer.run start zk server on port:58526
[junit4:junit4] 2> 176095 T524 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 176099 T531 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@345c4417 name:ZooKeeperConnection Watcher:127.0.0.1:58526 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 176100 T524 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 176100 T524 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 176116 T524 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 176118 T533 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7f5f1166 name:ZooKeeperConnection Watcher:127.0.0.1:58526/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 176119 T524 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 176119 T524 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 176125 T524 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 176128 T524 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 176136 T524 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 176139 T524 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 176140 T524 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 176152 T524 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 176153 T524 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 176287 T524 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 176288 T524 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 176291 T524 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 176292 T524 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 176296 T524 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 176296 T524 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 176300 T524 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 176301 T524 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 176304 T524 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 176305 T524 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 176308 T524 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 176309 T524 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 176313 T524 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 176314 T524 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 176595 T524 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 176598 T524 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:58529
[junit4:junit4] 2> 176599 T524 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 176600 T524 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 176600 T524 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372099420124
[junit4:junit4] 2> 176601 T524 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372099420124/solr.xml
[junit4:junit4] 2> 176601 T524 oasc.CoreContainer.<init> New CoreContainer 766211742
[junit4:junit4] 2> 176602 T524 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372099420124/'
[junit4:junit4] 2> 176603 T524 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372099420124/'
[junit4:junit4] 2> 176734 T524 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 176735 T524 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 176736 T524 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 176736 T524 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 176737 T524 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 176737 T524 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 176738 T524 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 176739 T524 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 176739 T524 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 176740 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 176759 T524 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 176760 T524 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58526/solr
[junit4:junit4] 2> 176760 T524 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 176762 T524 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 176765 T544 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@390f451d name:ZooKeeperConnection Watcher:127.0.0.1:58526 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 176766 T524 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 176804 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 176818 T524 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 176820 T546 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@475144fb name:ZooKeeperConnection Watcher:127.0.0.1:58526/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 176821 T524 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 176885 T524 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 176890 T524 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 176940 T524 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 176943 T524 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58529_
[junit4:junit4] 2> 176950 T524 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58529_
[junit4:junit4] 2> 176954 T524 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 176968 T524 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 176971 T524 oasc.Overseer.start Overseer (id=89921907576340483-127.0.0.1:58529_-n_0000000000) starting
[junit4:junit4] 2> 176981 T524 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 176997 T548 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 176998 T524 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 177001 T524 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 177013 T524 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 177016 T547 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 177020 T549 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 177021 T549 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 178521 T547 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 178522 T547 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "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:58529_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58529"}
[junit4:junit4] 2> 178522 T547 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 178523 T547 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 178543 T546 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> 179025 T549 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372099420124/collection1
[junit4:junit4] 2> 179025 T549 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 179026 T549 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 179026 T549 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 179028 T549 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372099420124/collection1/'
[junit4:junit4] 2> 179030 T549 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1372099420124/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 179030 T549 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1372099420124/collection1/lib/README' to classloader
[junit4:junit4] 2> 179100 T549 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 179161 T549 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 179263 T549 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 179279 T549 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 179860 T549 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 179864 T549 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 179866 T549 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 179872 T549 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 179916 T549 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 179917 T549 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372099420124/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372099419797/control/data/
[junit4:junit4] 2> 179917 T549 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@68208f7d
[junit4:junit4] 2> 179918 T549 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 179919 T549 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372099419797/control/data
[junit4:junit4] 2> 179919 T549 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372099419797/control/data/index/
[junit4:junit4] 2> 179920 T549 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372099419797/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 179920 T549 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372099419797/control/data/index
[junit4:junit4] 2> 179926 T549 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6532546d lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ec4c253),segFN=segments_1,generation=1}
[junit4:junit4] 2> 179926 T549 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 179930 T549 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 179930 T549 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 179931 T549 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 179932 T549 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 179933 T549 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 179933 T549 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 179934 T549 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 179935 T549 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 179935 T549 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 179952 T549 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 179960 T549 oass.SolrIndexSearcher.<init> Opening Searcher@51d06bd9 main
[junit4:junit4] 2> 179960 T549 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372099419797/control/data/tlog
[junit4:junit4] 2> 179962 T549 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 179962 T549 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 179967 T550 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@51d06bd9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 179970 T549 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 179971 T549 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58529 collection:control_collection shard:shard1
[junit4:junit4] 2> 179972 T549 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 179992 T549 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 179995 T549 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 179996 T549 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 179996 T549 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58529/collection1/
[junit4:junit4] 2> 179996 T549 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 179997 T549 oasc.SyncStrategy.syncToMe http://127.0.0.1:58529/collection1/ has no replicas
[junit4:junit4] 2> 179997 T549 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58529/collection1/
[junit4:junit4] 2> 179997 T549 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 180047 T547 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 180056 T546 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> 180106 T549 oasc.ZkController.register We are http://127.0.0.1:58529/collection1/ and leader is http://127.0.0.1:58529/collection1/
[junit4:junit4] 2> 180106 T549 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58529
[junit4:junit4] 2> 180106 T549 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 180107 T549 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 180107 T549 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 180109 T549 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 180110 T524 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 180111 T524 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 180112 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 180130 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 180132 T524 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 180135 T553 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@31615345 name:ZooKeeperConnection Watcher:127.0.0.1:58526/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 180135 T524 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 180137 T524 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 180140 T524 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 180408 T524 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 180411 T524 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:58534
[junit4:junit4] 2> 180412 T524 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 180413 T524 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 180413 T524 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372099423946
[junit4:junit4] 2> 180414 T524 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372099423946/solr.xml
[junit4:junit4] 2> 180414 T524 oasc.CoreContainer.<init> New CoreContainer 2049849175
[junit4:junit4] 2> 180415 T524 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372099423946/'
[junit4:junit4] 2> 180416 T524 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372099423946/'
[junit4:junit4] 2> 180547 T524 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 180548 T524 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 180548 T524 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 180549 T524 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 180549 T524 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 180550 T524 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 180551 T524 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 180551 T524 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 180552 T524 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 180552 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 180571 T524 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 180572 T524 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58526/solr
[junit4:junit4] 2> 180572 T524 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 180574 T524 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 180577 T564 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@dc9b684 name:ZooKeeperConnection Watcher:127.0.0.1:58526 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 180578 T524 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 180592 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 180606 T524 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 180608 T566 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6ba3c0d0 name:ZooKeeperConnection Watcher:127.0.0.1:58526/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 180608 T524 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 180620 T524 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 181563 T547 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 181564 T547 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "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:58529_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58529"}
[junit4:junit4] 2> 181629 T566 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> 181629 T524 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58534_
[junit4:junit4] 2> 181629 T546 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> 181629 T553 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> 181703 T524 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58534_
[junit4:junit4] 2> 181731 T566 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 181731 T553 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 181731 T566 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> 181731 T546 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 181732 T553 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> 181732 T546 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> 181739 T567 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 181739 T567 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 183207 T547 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 183208 T547 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[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:58534_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58534"}
[junit4:junit4] 2> 183208 T547 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 183209 T547 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 183232 T566 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> 183232 T553 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> 183232 T546 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> 183743 T567 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372099423946/collection1
[junit4:junit4] 2> 183743 T567 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 183744 T567 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 183745 T567 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 183747 T567 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372099423946/collection1/'
[junit4:junit4] 2> 183748 T567 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1372099423946/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 183749 T567 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1372099423946/collection1/lib/README' to classloader
[junit4:junit4] 2> 183804 T567 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 183866 T567 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 183967 T567 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 183983 T567 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 184577 T567 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 184580 T567 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 184582 T567 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 184587 T567 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 184620 T567 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 184621 T567 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372099423946/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty1/
[junit4:junit4] 2> 184621 T567 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@68208f7d
[junit4:junit4] 2> 184623 T567 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 184623 T567 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty1
[junit4:junit4] 2> 184623 T567 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty1/index/
[junit4:junit4] 2> 184624 T567 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 184624 T567 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty1/index
[junit4:junit4] 2> 184627 T567 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@400ee86 lockFactory=org.apache.lucene.store.NativeFSLockFactory@49dca937),segFN=segments_1,generation=1}
[junit4:junit4] 2> 184628 T567 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 184630 T567 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 184631 T567 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 184632 T567 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 184633 T567 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 184634 T567 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 184634 T567 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 184635 T567 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 184635 T567 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 184636 T567 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 184647 T567 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 184652 T567 oass.SolrIndexSearcher.<init> Opening Searcher@12eafc34 main
[junit4:junit4] 2> 184652 T567 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty1/tlog
[junit4:junit4] 2> 184653 T567 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 184653 T567 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 184659 T568 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12eafc34 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 184661 T567 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 184661 T567 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58534 collection:collection1 shard:shard1
[junit4:junit4] 2> 184662 T567 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 184688 T567 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 184692 T567 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 184693 T567 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 184693 T567 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58534/collection1/
[junit4:junit4] 2> 184693 T567 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 184693 T567 oasc.SyncStrategy.syncToMe http://127.0.0.1:58534/collection1/ has no replicas
[junit4:junit4] 2> 184694 T567 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58534/collection1/
[junit4:junit4] 2> 184694 T567 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 184740 T547 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 184757 T566 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> 184757 T546 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> 184757 T553 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> 184763 T567 oasc.ZkController.register We are http://127.0.0.1:58534/collection1/ and leader is http://127.0.0.1:58534/collection1/
[junit4:junit4] 2> 184763 T567 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58534
[junit4:junit4] 2> 184763 T567 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 184764 T567 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 184764 T567 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 184770 T567 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 184772 T524 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 184772 T524 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 184773 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 184961 T524 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 184964 T524 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:58537
[junit4:junit4] 2> 184965 T524 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 184965 T524 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 184966 T524 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372099428590
[junit4:junit4] 2> 184966 T524 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372099428590/solr.xml
[junit4:junit4] 2> 184966 T524 oasc.CoreContainer.<init> New CoreContainer 1767679095
[junit4:junit4] 2> 184967 T524 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372099428590/'
[junit4:junit4] 2> 184967 T524 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372099428590/'
[junit4:junit4] 2> 185072 T524 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 185073 T524 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 185073 T524 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 185074 T524 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 185075 T524 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 185075 T524 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 185076 T524 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 185076 T524 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 185077 T524 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 185077 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 185094 T524 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 185095 T524 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58526/solr
[junit4:junit4] 2> 185096 T524 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 185097 T524 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 185100 T580 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@23e43290 name:ZooKeeperConnection Watcher:127.0.0.1:58526 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 185101 T524 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 185119 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 185127 T524 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 185129 T582 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3b79f360 name:ZooKeeperConnection Watcher:127.0.0.1:58526/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 185129 T524 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 185140 T524 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 186144 T524 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58537_
[junit4:junit4] 2> 186146 T524 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58537_
[junit4:junit4] 2> 186150 T553 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 186150 T582 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 186150 T553 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> 186150 T546 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 186150 T566 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 186151 T546 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> 186152 T566 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> 186170 T583 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 186170 T583 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 186272 T547 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 186273 T547 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[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:58534_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58534"}
[junit4:junit4] 2> 186278 T547 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[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:58537_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58537"}
[junit4:junit4] 2> 186278 T547 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 186278 T547 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 186290 T566 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> 186290 T546 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> 186290 T553 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> 186290 T582 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> 187173 T583 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372099428590/collection1
[junit4:junit4] 2> 187173 T583 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 187174 T583 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 187175 T583 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 187177 T583 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372099428590/collection1/'
[junit4:junit4] 2> 187178 T583 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1372099428590/collection1/lib/README' to classloader
[junit4:junit4] 2> 187179 T583 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1372099428590/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 187233 T583 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 187294 T583 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 187395 T583 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 187406 T583 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 187985 T583 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 187989 T583 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 187991 T583 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 187997 T583 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 188038 T583 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 188039 T583 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372099428590/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty2/
[junit4:junit4] 2> 188039 T583 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@68208f7d
[junit4:junit4] 2> 188040 T583 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 188041 T583 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty2
[junit4:junit4] 2> 188041 T583 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty2/index/
[junit4:junit4] 2> 188042 T583 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 188043 T583 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty2/index
[junit4:junit4] 2> 188047 T583 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e084ca5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d153029),segFN=segments_1,generation=1}
[junit4:junit4] 2> 188047 T583 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 188051 T583 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 188052 T583 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 188053 T583 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 188054 T583 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 188055 T583 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 188055 T583 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 188056 T583 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 188057 T583 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 188057 T583 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 188074 T583 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 188081 T583 oass.SolrIndexSearcher.<init> Opening Searcher@250a512d main
[junit4:junit4] 2> 188081 T583 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty2/tlog
[junit4:junit4] 2> 188082 T583 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 188083 T583 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 188090 T584 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@250a512d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 188093 T583 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 188093 T583 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58537 collection:collection1 shard:shard2
[junit4:junit4] 2> 188094 T583 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 188119 T583 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 188122 T583 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 188122 T583 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 188123 T583 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58537/collection1/
[junit4:junit4] 2> 188123 T583 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 188123 T583 oasc.SyncStrategy.syncToMe http://127.0.0.1:58537/collection1/ has no replicas
[junit4:junit4] 2> 188124 T583 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58537/collection1/
[junit4:junit4] 2> 188124 T583 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 189307 T547 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 189325 T566 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> 189325 T546 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> 189325 T582 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> 189325 T553 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> 189354 T583 oasc.ZkController.register We are http://127.0.0.1:58537/collection1/ and leader is http://127.0.0.1:58537/collection1/
[junit4:junit4] 2> 189354 T583 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58537
[junit4:junit4] 2> 189354 T583 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 189355 T583 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 189355 T583 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 189357 T583 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 189358 T524 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 189359 T524 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 189360 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 189643 T524 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 189646 T524 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:58540
[junit4:junit4] 2> 189647 T524 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 189648 T524 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 189648 T524 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372099433183
[junit4:junit4] 2> 189649 T524 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372099433183/solr.xml
[junit4:junit4] 2> 189649 T524 oasc.CoreContainer.<init> New CoreContainer 406889757
[junit4:junit4] 2> 189650 T524 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372099433183/'
[junit4:junit4] 2> 189651 T524 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372099433183/'
[junit4:junit4] 2> 189780 T524 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 189781 T524 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 189781 T524 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 189782 T524 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 189782 T524 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 189783 T524 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 189783 T524 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 189784 T524 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 189784 T524 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 189785 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 189802 T524 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 189803 T524 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58526/solr
[junit4:junit4] 2> 189804 T524 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 189805 T524 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 189808 T596 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f32b888 name:ZooKeeperConnection Watcher:127.0.0.1:58526 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 189809 T524 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 189825 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 189837 T524 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 189839 T598 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7d2aa2c7 name:ZooKeeperConnection Watcher:127.0.0.1:58526/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 189839 T524 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 189850 T524 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 190832 T547 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 190833 T547 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[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:58537_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58537"}
[junit4:junit4] 2> 190838 T598 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> 190838 T546 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> 190838 T582 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> 190838 T553 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> 190838 T566 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> 190854 T524 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58540_
[junit4:junit4] 2> 190856 T524 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58540_
[junit4:junit4] 2> 190859 T598 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> 190859 T582 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> 190859 T566 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 190859 T546 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 190859 T553 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 190860 T546 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> 190860 T566 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> 190861 T582 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 190861 T598 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 190860 T553 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> 190872 T599 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 190873 T599 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 192344 T547 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 192345 T547 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:58540_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58540"}
[junit4:junit4] 2> 192345 T547 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 192346 T547 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 192371 T566 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> 192371 T546 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> 192371 T582 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> 192371 T598 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> 192371 T553 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> 192876 T599 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372099433183/collection1
[junit4:junit4] 2> 192876 T599 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 192877 T599 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 192877 T599 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 192879 T599 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372099433183/collection1/'
[junit4:junit4] 2> 192881 T599 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1372099433183/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 192881 T599 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1372099433183/collection1/lib/README' to classloader
[junit4:junit4] 2> 192945 T599 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 193006 T599 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 193108 T599 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 193119 T599 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 193716 T599 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 193721 T599 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 193723 T599 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 193729 T599 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 193772 T599 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 193772 T599 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372099433183/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty3/
[junit4:junit4] 2> 193773 T599 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@68208f7d
[junit4:junit4] 2> 193773 T599 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 193774 T599 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty3
[junit4:junit4] 2> 193775 T599 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty3/index/
[junit4:junit4] 2> 193775 T599 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 193776 T599 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty3/index
[junit4:junit4] 2> 193780 T599 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@584f5c87 lockFactory=org.apache.lucene.store.NativeFSLockFactory@34ab608b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 193781 T599 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 193785 T599 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 193785 T599 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 193786 T599 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 193787 T599 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 193788 T599 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 193788 T599 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 193789 T599 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 193790 T599 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 193791 T599 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 193808 T599 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 193815 T599 oass.SolrIndexSearcher.<init> Opening Searcher@2c35fbb6 main
[junit4:junit4] 2> 193816 T599 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty3/tlog
[junit4:junit4] 2> 193817 T599 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 193818 T599 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 193825 T600 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2c35fbb6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 193828 T599 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 193828 T599 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58540 collection:collection1 shard:shard1
[junit4:junit4] 2> 193836 T599 oasc.ZkController.register We are http://127.0.0.1:58540/collection1/ and leader is http://127.0.0.1:58534/collection1/
[junit4:junit4] 2> 193836 T599 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58540
[junit4:junit4] 2> 193836 T599 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 193837 T599 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C137 name=collection1 org.apache.solr.core.SolrCore@748860cc url=http://127.0.0.1:58540/collection1 node=127.0.0.1:58540_ C137_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:58540_, base_url=http://127.0.0.1:58540}
[junit4:junit4] 2> 193837 T601 C137 P58540 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 193838 T599 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 193838 T601 C137 P58540 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 193839 T601 C137 P58540 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 193839 T601 C137 P58540 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 193840 T524 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 193840 T524 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 193841 T601 C137 P58540 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 193841 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 193869 T556 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 193877 T547 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 193877 T547 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:58540_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58540"}
[junit4:junit4] 2> 193891 T598 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> 193891 T553 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> 193891 T566 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> 193891 T546 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> 193891 T582 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> 194141 T524 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 194144 T524 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:58547
[junit4:junit4] 2> 194145 T524 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 194146 T524 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 194146 T524 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372099437673
[junit4:junit4] 2> 194147 T524 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372099437673/solr.xml
[junit4:junit4] 2> 194147 T524 oasc.CoreContainer.<init> New CoreContainer 1289688134
[junit4:junit4] 2> 194148 T524 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372099437673/'
[junit4:junit4] 2> 194149 T524 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372099437673/'
[junit4:junit4] 2> 194277 T524 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 194278 T524 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 194279 T524 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 194280 T524 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 194280 T524 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 194281 T524 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 194281 T524 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 194282 T524 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 194282 T524 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 194283 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 194302 T524 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 194303 T524 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58526/solr
[junit4:junit4] 2> 194304 T524 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 194305 T524 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 194308 T613 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@58738988 name:ZooKeeperConnection Watcher:127.0.0.1:58526 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 194309 T524 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 194319 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 194334 T524 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 194336 T615 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4359a5f2 name:ZooKeeperConnection Watcher:127.0.0.1:58526/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 194336 T524 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 194348 T524 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 194870 T556 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 194870 T556 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:58540_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 195352 T524 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58547_
[junit4:junit4] 2> 195354 T524 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58547_
[junit4:junit4] 2> 195357 T598 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> 195357 T582 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> 195358 T615 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 195358 T546 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 195358 T566 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 195358 T553 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 195360 T598 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 195359 T566 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> 195359 T546 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> 195360 T553 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> 195367 T582 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 195372 T616 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 195373 T616 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 195395 T547 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 195396 T547 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:58547_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58547"}
[junit4:junit4] 2> 195397 T547 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 195397 T547 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 195409 T598 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> 195409 T546 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> 195409 T615 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> 195409 T582 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> 195409 T553 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> 195409 T566 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> 196376 T616 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372099437673/collection1
[junit4:junit4] 2> 196376 T616 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 196378 T616 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 196378 T616 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 196380 T616 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372099437673/collection1/'
[junit4:junit4] 2> 196382 T616 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1372099437673/collection1/lib/README' to classloader
[junit4:junit4] 2> 196383 T616 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1372099437673/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 196437 T616 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 196509 T616 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 196611 T616 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 196620 T616 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C138 name=collection1 org.apache.solr.core.SolrCore@748860cc url=http://127.0.0.1:58540/collection1 node=127.0.0.1:58540_ C138_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:58540_, base_url=http://127.0.0.1:58540}
[junit4:junit4] 2> 196873 T601 C138 P58540 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:58534/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 196873 T601 C138 P58540 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58540 START replicas=[http://127.0.0.1:58534/collection1/] nUpdates=100
[junit4:junit4] 2> 196874 T601 C138 P58540 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 196875 T601 C138 P58540 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 196875 T601 C138 P58540 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 196875 T601 C138 P58540 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 196876 T601 C138 P58540 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 196877 T601 C138 P58540 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:58534/collection1/. core=collection1
[junit4:junit4] 2> 196877 T601 C138 P58540 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C139 name=collection1 org.apache.solr.core.SolrCore@15b1a7b url=http://127.0.0.1:58534/collection1 node=127.0.0.1:58534_ C139_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:58534_, base_url=http://127.0.0.1:58534, leader=true}
[junit4:junit4] 2> 196896 T557 C139 P58534 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 196903 T558 C139 P58534 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 196907 T558 C139 P58534 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@400ee86 lockFactory=org.apache.lucene.store.NativeFSLockFactory@49dca937),segFN=segments_1,generation=1}
[junit4:junit4] 2> 196908 T558 C139 P58534 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 196909 T558 C139 P58534 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@400ee86 lockFactory=org.apache.lucene.store.NativeFSLockFactory@49dca937),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@400ee86 lockFactory=org.apache.lucene.store.NativeFSLockFactory@49dca937),segFN=segments_2,generation=2}
[junit4:junit4] 2> 196909 T558 C139 P58534 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 196910 T558 C139 P58534 oass.SolrIndexSearcher.<init> Opening Searcher@35f25f88 realtime
[junit4:junit4] 2> 196911 T558 C139 P58534 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 196911 T558 C139 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> ASYNC NEW_CORE C140 name=collection1 org.apache.solr.core.SolrCore@748860cc url=http://127.0.0.1:58540/collection1 node=127.0.0.1:58540_ C140_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:58540_, base_url=http://127.0.0.1:58540}
[junit4:junit4] 2> 196912 T601 C140 P58540 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 196913 T601 C140 P58540 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 196915 T559 C139 P58534 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 196916 T559 C139 P58534 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 196917 T601 C140 P58540 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 196917 T601 C140 P58540 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 196917 T601 C140 P58540 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 196921 T559 C139 P58534 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 196922 T601 C140 P58540 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 196923 T601 C140 P58540 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty3/index.20130624144400728
[junit4:junit4] 2> 196923 T601 C140 P58540 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@66ef2238 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f80b005) fullCopy=false
[junit4:junit4] 2> 196927 T559 C139 P58534 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 196928 T601 C140 P58540 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 196930 T601 C140 P58540 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 196930 T601 C140 P58540 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 196933 T601 C140 P58540 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@584f5c87 lockFactory=org.apache.lucene.store.NativeFSLockFactory@34ab608b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@584f5c87 lockFactory=org.apache.lucene.store.NativeFSLockFactory@34ab608b),segFN=segments_2,generation=2}
[junit4:junit4] 2> 196933 T601 C140 P58540 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 196934 T601 C140 P58540 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 196934 T601 C140 P58540 oass.SolrIndexSearcher.<init> Opening Searcher@1d442833 main
[junit4:junit4] 2> 196936 T600 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d442833 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 196937 T601 C140 P58540 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty3/index.20130624144400728 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty3/index.20130624144400728;done=true>>]
[junit4:junit4] 2> 196937 T601 C140 P58540 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty3/index.20130624144400728
[junit4:junit4] 2> 196937 T601 C140 P58540 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty3/index.20130624144400728
[junit4:junit4] 2> 196938 T601 C140 P58540 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 196938 T601 C140 P58540 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 196938 T601 C140 P58540 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 196939 T601 C140 P58540 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 196943 T601 C140 P58540 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 197207 T616 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 197211 T616 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 197214 T616 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 197220 T616 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 197255 T616 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 197256 T616 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372099437673/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4/
[junit4:junit4] 2> 197256 T616 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@68208f7d
[junit4:junit4] 2> 197257 T616 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 197258 T616 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4
[junit4:junit4] 2> 197258 T616 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4/index/
[junit4:junit4] 2> 197259 T616 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 197259 T616 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4/index
[junit4:junit4] 2> 197264 T616 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@612baafc lockFactory=org.apache.lucene.store.NativeFSLockFactory@38756f7f),segFN=segments_1,generation=1}
[junit4:junit4] 2> 197264 T616 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 197268 T616 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 197268 T616 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 197269 T616 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 197270 T616 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 197271 T616 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 197272 T616 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 197273 T616 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 197274 T616 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 197275 T616 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 197291 T616 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 197299 T616 oass.SolrIndexSearcher.<init> Opening Searcher@21ba659c main
[junit4:junit4] 2> 197299 T616 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4/tlog
[junit4:junit4] 2> 197301 T616 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 197301 T616 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 197308 T619 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@21ba659c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 197311 T616 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 197311 T616 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58547 collection:collection1 shard:shard2
[junit4:junit4] 2> 197315 T616 oasc.ZkController.register We are http://127.0.0.1:58547/collection1/ and leader is http://127.0.0.1:58537/collection1/
[junit4:junit4] 2> 197316 T616 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58547
[junit4:junit4] 2> 197316 T616 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 197316 T616 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C141 name=collection1 org.apache.solr.core.SolrCore@63e78458 url=http://127.0.0.1:58547/collection1 node=127.0.0.1:58547_ C141_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:58547_, base_url=http://127.0.0.1:58547}
[junit4:junit4] 2> 197317 T620 C141 P58547 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 197317 T616 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 197318 T620 C141 P58547 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 197318 T620 C141 P58547 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 197319 T620 C141 P58547 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 197319 T524 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 197320 T524 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 197320 T524 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 197321 T620 C141 P58547 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 197347 T524 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 197348 T524 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 197349 T572 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 197349 T524 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 197350 T524 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 198352 T524 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 198416 T547 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 198418 T547 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:58540_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58540"}
[junit4:junit4] 2> 198427 T547 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:58547_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58547"}
[junit4:junit4] 2> 198445 T566 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> 198445 T546 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> 198445 T553 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> 198445 T582 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> 198445 T598 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> 198446 T615 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> 199351 T572 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 199351 T572 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:58547_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 199355 T524 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 200358 T524 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C141_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:58547_, base_url=http://127.0.0.1:58547}
[junit4:junit4] 2> 201354 T620 C141 P58547 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:58537/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 201354 T620 C141 P58547 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58547 START replicas=[http://127.0.0.1:58537/collection1/] nUpdates=100
[junit4:junit4] 2> 201356 T620 C141 P58547 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 201356 T620 C141 P58547 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 201356 T620 C141 P58547 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 201357 T620 C141 P58547 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 201357 T620 C141 P58547 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 201358 T620 C141 P58547 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:58537/collection1/. core=collection1
[junit4:junit4] 2> 201358 T620 C141 P58547 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 201361 T524 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C142 name=collection1 org.apache.solr.core.SolrCore@25601fcf url=http://127.0.0.1:58537/collection1 node=127.0.0.1:58537_ C142_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:58537_, base_url=http://127.0.0.1:58537, leader=true}
[junit4:junit4] 2> 201365 T573 C142 P58537 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 201378 T574 C142 P58537 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 201383 T574 C142 P58537 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e084ca5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d153029),segFN=segments_1,generation=1}
[junit4:junit4] 2> 201386 T574 C142 P58537 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 201387 T574 C142 P58537 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e084ca5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d153029),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e084ca5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d153029),segFN=segments_2,generation=2}
[junit4:junit4] 2> 201388 T574 C142 P58537 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 201389 T574 C142 P58537 oass.SolrIndexSearcher.<init> Opening Searcher@410b68f6 realtime
[junit4:junit4] 2> 201389 T574 C142 P58537 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 201390 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 12
[junit4:junit4] 2> 201391 T620 C141 P58547 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 201392 T620 C141 P58547 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 201395 T575 C142 P58537 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 201395 T575 C142 P58537 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 201396 T620 C141 P58547 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 201397 T620 C141 P58547 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 201397 T620 C141 P58547 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 201401 T575 C142 P58537 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 201402 T620 C141 P58547 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 201403 T620 C141 P58547 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4/index.20130624144405208
[junit4:junit4] 2> 201403 T620 C141 P58547 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@2438d817 lockFactory=org.apache.lucene.store.NativeFSLockFactory@192e3bbf) fullCopy=false
[junit4:junit4] 2> 201406 T575 C142 P58537 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 201408 T620 C141 P58547 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 201409 T620 C141 P58547 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 201410 T620 C141 P58547 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 201412 T620 C141 P58547 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@612baafc lockFactory=org.apache.lucene.store.NativeFSLockFactory@38756f7f),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@612baafc lockFactory=org.apache.lucene.store.NativeFSLockFactory@38756f7f),segFN=segments_2,generation=2}
[junit4:junit4] 2> 201412 T620 C141 P58547 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 201413 T620 C141 P58547 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 201413 T620 C141 P58547 oass.SolrIndexSearcher.<init> Opening Searcher@4cf22d2a main
[junit4:junit4] 2> 201415 T619 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4cf22d2a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 201416 T620 C141 P58547 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4/index.20130624144405208 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4/index.20130624144405208;done=true>>]
[junit4:junit4] 2> 201416 T620 C141 P58547 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4/index.20130624144405208
[junit4:junit4] 2> 201417 T620 C141 P58547 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4/index.20130624144405208
[junit4:junit4] 2> 201417 T620 C141 P58547 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 201417 T620 C141 P58547 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 201418 T620 C141 P58547 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 201418 T620 C141 P58547 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 201420 T620 C141 P58547 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 201459 T547 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 201461 T547 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:58547_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58547"}
[junit4:junit4] 2> 201516 T598 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> 201516 T615 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> 201516 T546 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> 201516 T582 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> 201516 T566 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> 201516 T553 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> 202364 T524 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 202366 T524 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C143 name=collection1 org.apache.solr.core.SolrCore@3517402 url=http://127.0.0.1:58529/collection1 node=127.0.0.1:58529_ C143_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:58529_, base_url=http://127.0.0.1:58529, leader=true}
[junit4:junit4] 2> 202375 T536 C143 P58529 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 202379 T536 C143 P58529 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6532546d lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ec4c253),segFN=segments_1,generation=1}
[junit4:junit4] 2> 202380 T536 C143 P58529 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 202381 T536 C143 P58529 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6532546d lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ec4c253),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6532546d lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ec4c253),segFN=segments_2,generation=2}
[junit4:junit4] 2> 202381 T536 C143 P58529 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 202382 T536 C143 P58529 oass.SolrIndexSearcher.<init> Opening Searcher@52cfcf01 main
[junit4:junit4] 2> 202383 T536 C143 P58529 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 202384 T550 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@52cfcf01 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 202385 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4] 2> ASYNC NEW_CORE C144 name=collection1 org.apache.solr.core.SolrCore@15b1a7b url=http://127.0.0.1:58534/collection1 node=127.0.0.1:58534_ C144_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:58534_, base_url=http://127.0.0.1:58534, leader=true}
[junit4:junit4] 2> 202399 T560 C144 P58534 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:58534/collection1/, StdNode: http://127.0.0.1:58540/collection1/, StdNode: http://127.0.0.1:58537/collection1/, StdNode: http://127.0.0.1:58547/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 202403 T561 C144 P58534 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 202403 T576 C142 P58537 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 202405 T561 C144 P58534 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@400ee86 lockFactory=org.apache.lucene.store.NativeFSLockFactory@49dca937),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@400ee86 lockFactory=org.apache.lucene.store.NativeFSLockFactory@49dca937),segFN=segments_3,generation=3}
[junit4:junit4] 2> 202407 T576 C142 P58537 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e084ca5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d153029),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e084ca5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d153029),segFN=segments_3,generation=3}
[junit4:junit4] 2> 202407 T561 C144 P58534 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 202408 T576 C142 P58537 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 202408 T561 C144 P58534 oass.SolrIndexSearcher.<init> Opening Searcher@1fbafacc main
[junit4:junit4] 2> 202409 T576 C142 P58537 oass.SolrIndexSearcher.<init> Opening Searcher@2c5ae898 main
[junit4:junit4] 2> 202409 T561 C144 P58534 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 202410 T576 C142 P58537 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 202411 T568 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1fbafacc main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 202411 T584 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2c5ae898 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 202411 T561 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 202412 T576 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> C141_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:58547_, base_url=http://127.0.0.1:58547}
[junit4:junit4] 2> 202413 T605 C141 P58547 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C145 name=collection1 org.apache.solr.core.SolrCore@748860cc url=http://127.0.0.1:58540/collection1 node=127.0.0.1:58540_ C145_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:58540_, base_url=http://127.0.0.1:58540}
[junit4:junit4] 2> 202413 T588 C145 P58540 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 202414 T605 C141 P58547 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@612baafc lockFactory=org.apache.lucene.store.NativeFSLockFactory@38756f7f),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@612baafc lockFactory=org.apache.lucene.store.NativeFSLockFactory@38756f7f),segFN=segments_3,generation=3}
[junit4:junit4] 2> 202415 T588 C145 P58540 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@584f5c87 lockFactory=org.apache.lucene.store.NativeFSLockFactory@34ab608b),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@584f5c87 lockFactory=org.apache.lucene.store.NativeFSLockFactory@34ab608b),segFN=segments_3,generation=3}
[junit4:junit4] 2> 202415 T605 C141 P58547 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 202416 T588 C145 P58540 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 202416 T605 C141 P58547 oass.SolrIndexSearcher.<init> Opening Searcher@795cc75f main
[junit4:junit4] 2> 202417 T588 C145 P58540 oass.SolrIndexSearcher.<init> Opening Searcher@6ee3ee5a main
[junit4:junit4] 2> 202417 T605 C141 P58547 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 202418 T619 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@795cc75f main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 202418 T588 C145 P58540 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 202419 T605 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 202419 T600 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6ee3ee5a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 202420 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 202421 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 22
[junit4:junit4] 2> 202423 T524 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 202427 T562 C144 P58534 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 202430 T589 C145 P58540 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 202433 T577 C142 P58537 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 202436 T606 C141 P58547 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 204443 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438750551045046272)} 0 2
[junit4:junit4] 2> 204452 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438750551051337728&update.from=http://127.0.0.1:58534/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438750551051337728)} 0 2
[junit4:junit4] 2> 204459 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438750551055532032&update.from=http://127.0.0.1:58537/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438750551055532032)} 0 2
[junit4:junit4] 2> 204460 T576 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438750551055532032)} 0 10
[junit4:junit4] 2> 204461 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438750551051337728)} 0 15
[junit4:junit4] 2> 204466 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1438750551070212096)]} 0 2
[junit4:junit4] 2> 204477 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1438750551076503552)]} 0 2
[junit4:junit4] 2> 204478 T578 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!0 (1438750551076503552)]} 0 7
[junit4:junit4] 2> 204479 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0]} 0 11
[junit4:junit4] 2> 204483 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1438750551089086464)]} 0 1
[junit4:junit4] 2> 204496 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1438750551096426496)]} 0 2
[junit4:junit4] 2> 204497 T556 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!1 (1438750551096426496)]} 0 7
[junit4:junit4] 2> 204498 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1]} 0 11
[junit4:junit4] 2> 204502 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1438750551109009408)]} 0 1
[junit4:junit4] 2> 204514 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1438750551117398016)]} 0 1
[junit4:junit4] 2> 204515 T556 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!2 (1438750551117398016)]} 0 6
[junit4:junit4] 2> 204516 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2]} 0 10
[junit4:junit4] 2> 204520 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1438750551127883776)]} 0 1
[junit4:junit4] 2> 204532 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1438750551134175232)]} 0 2
[junit4:junit4] 2> 204533 T572 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58540/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!3 (1438750551134175232)]} 0 7
[junit4:junit4] 2> 204534 T590 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3]} 0 11
[junit4:junit4] 2> 204538 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1438750551146758144)]} 0 1
[junit4:junit4] 2> 204551 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1438750551155146752)]} 0 2
[junit4:junit4] 2> 204552 T576 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!4 (1438750551155146752)]} 0 7
[junit4:junit4] 2> 204552 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4]} 0 10
[junit4:junit4] 2> 204557 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1438750551166681088)]} 0 1
[junit4:junit4] 2> 204569 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1438750551174021120)]} 0 2
[junit4:junit4] 2> 204569 T578 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1438750551174021120)]} 0 6
[junit4:junit4] 2> 204570 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5]} 0 10
[junit4:junit4] 2> 204575 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1438750551185555456)]} 0 1
[junit4:junit4] 2> 204586 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1438750551192895488)]} 0 1
[junit4:junit4] 2> 204587 T556 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!6 (1438750551192895488)]} 0 6
[junit4:junit4] 2> 204588 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6]} 0 10
[junit4:junit4] 2> 204592 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1438750551203381248)]} 0 1
[junit4:junit4] 2> 204600 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1438750551207575552)]} 0 1
[junit4:junit4] 2> 204602 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1438750551207575552)]} 0 7
[junit4:junit4] 2> 204606 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1438750551218061312)]} 0 1
[junit4:junit4] 2> 204615 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1438750551222255616)]} 0 2
[junit4:junit4] 2> 204616 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1438750551222255616)]} 0 6
[junit4:junit4] 2> 204620 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1438750551232741376)]} 0 1
[junit4:junit4] 2> 204632 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1438750551240081408)]} 0 2
[junit4:junit4] 2> 204633 T558 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58540/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!9 (1438750551240081408)]} 0 7
[junit4:junit4] 2> 204634 T590 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9]} 0 10
[junit4:junit4] 2> 204639 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1438750551251615744)]} 0 2
[junit4:junit4] 2> 204649 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1438750551257907200)]} 0 2
[junit4:junit4] 2> 204650 T631 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!10 (1438750551257907200)]} 0 7
[junit4:junit4] 2> 204651 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10]} 0 10
[junit4:junit4] 2> 204656 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1438750551269441536)]} 0 2
[junit4:junit4] 2> 204665 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1438750551274684416)]} 0 2
[junit4:junit4] 2> 204665 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1438750551274684416)]} 0 6
[junit4:junit4] 2> 204671 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1438750551285170176)]} 0 2
[junit4:junit4] 2> 204682 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1438750551293558784)]} 0 1
[junit4:junit4] 2> 204683 T576 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!12 (1438750551293558784)]} 0 6
[junit4:junit4] 2> 204684 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12]} 0 10
[junit4:junit4] 2> 204689 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1438750551305093120)]} 0 1
[junit4:junit4] 2> 204699 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1438750551310336000)]} 0 2
[junit4:junit4] 2> 204700 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1438750551310336000)]} 0 7
[junit4:junit4] 2> 204704 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1438750551320821760)]} 0 1
[junit4:junit4] 2> 204717 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1438750551329210368)]} 0 2
[junit4:junit4] 2> 204718 T576 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!14 (1438750551329210368)]} 0 7
[junit4:junit4] 2> 204719 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14]} 0 11
[junit4:junit4] 2> 204723 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1438750551340744704)]} 0 1
[junit4:junit4] 2> 204736 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1438750551349133312)]} 0 2
[junit4:junit4] 2> 204737 T558 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58540/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!15 (1438750551349133312)]} 0 7
[junit4:junit4] 2> 204738 T590 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15]} 0 11
[junit4:junit4] 2> 204743 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1438750551360667648)]} 0 1
[junit4:junit4] 2> 204754 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1438750551369056256)]} 0 1
[junit4:junit4] 2> 204755 T556 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1438750551369056256)]} 0 6
[junit4:junit4] 2> 204756 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16]} 0 10
[junit4:junit4] 2> 204760 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1438750551379542016)]} 0 1
[junit4:junit4] 2> 204771 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1438750551386882048)]} 0 1
[junit4:junit4] 2> 204772 T578 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!17 (1438750551386882048)]} 0 6
[junit4:junit4] 2> 204773 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17]} 0 10
[junit4:junit4] 2> 204778 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1438750551398416384)]} 0 1
[junit4:junit4] 2> 204790 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1438750551406804992)]} 0 1
[junit4:junit4] 2> 204791 T631 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!18 (1438750551406804992)]} 0 6
[junit4:junit4] 2> 204792 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18]} 0 10
[junit4:junit4] 2> 204796 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1438750551417290752)]} 0 1
[junit4:junit4] 2> 204808 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1438750551425679360)]} 0 1
[junit4:junit4] 2> 204809 T558 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58540/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!19 (1438750551425679360)]} 0 6
[junit4:junit4] 2> 204810 T590 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19]} 0 10
[junit4:junit4] 2> 204814 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1438750551436165120)]} 0 1
[junit4:junit4] 2> 204826 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1438750551444553728)]} 0 1
[junit4:junit4] 2> 204827 T578 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!20 (1438750551444553728)]} 0 6
[junit4:junit4] 2> 204828 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20]} 0 10
[junit4:junit4] 2> 204832 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1438750551455039488)]} 0 1
[junit4:junit4] 2> 204841 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1438750551460282368)]} 0 1
[junit4:junit4] 2> 204842 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1438750551460282368)]} 0 6
[junit4:junit4] 2> 204846 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1438750551469719552)]} 0 1
[junit4:junit4] 2> 204854 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1438750551473913856)]} 0 1
[junit4:junit4] 2> 204855 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1438750551473913856)]} 0 6
[junit4:junit4] 2> 204859 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1438750551483351040)]} 0 1
[junit4:junit4] 2> 204869 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1438750551488593920)]} 0 2
[junit4:junit4] 2> 204870 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1438750551488593920)]} 0 7
[junit4:junit4] 2> 204874 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1438750551499079680)]} 0 1
[junit4:junit4] 2> 204887 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1438750551507468288)]} 0 2
[junit4:junit4] 2> 204887 T576 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!24 (1438750551507468288)]} 0 6
[junit4:junit4] 2> 204888 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24]} 0 10
[junit4:junit4] 2> 204893 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1438750551519002624)]} 0 1
[junit4:junit4] 2> 204901 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1438750551523196928)]} 0 1
[junit4:junit4] 2> 204902 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1438750551523196928)]} 0 6
[junit4:junit4] 2> 204906 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1438750551532634112)]} 0 1
[junit4:junit4] 2> 204918 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1438750551539974144)]} 0 2
[junit4:junit4] 2> 204919 T578 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!26 (1438750551539974144)]} 0 7
[junit4:junit4] 2> 204919 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26]} 0 10
[junit4:junit4] 2> 204924 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1438750551551508480)]} 0 1
[junit4:junit4] 2> 204936 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1438750551559897088)]} 0 1
[junit4:junit4] 2> 204937 T631 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!27 (1438750551559897088)]} 0 6
[junit4:junit4] 2> 204938 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27]} 0 10
[junit4:junit4] 2> 204942 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1438750551570382848)]} 0 1
[junit4:junit4] 2> 204953 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1438750551577722880)]} 0 1
[junit4:junit4] 2> 204954 T556 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!28 (1438750551577722880)]} 0 6
[junit4:junit4] 2> 204955 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28]} 0 10
[junit4:junit4] 2> 204959 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1438750551588208640)]} 0 1
[junit4:junit4] 2> 204971 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1438750551596597248)]} 0 1
[junit4:junit4] 2> 204972 T578 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1438750551596597248)]} 0 6
[junit4:junit4] 2> 204973 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29]} 0 10
[junit4:junit4] 2> 204977 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1438750551607083008)]} 0 1
[junit4:junit4] 2> 204989 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1438750551615471616)]} 0 1
[junit4:junit4] 2> 204990 T578 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!30 (1438750551615471616)]} 0 6
[junit4:junit4] 2> 204991 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30]} 0 10
[junit4:junit4] 2> 204995 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1438750551625957376)]} 0 1
[junit4:junit4] 2> 205007 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1438750551633297408)]} 0 2
[junit4:junit4] 2> 205008 T578 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1438750551633297408)]} 0 7
[junit4:junit4] 2> 205009 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31]} 0 11
[junit4:junit4] 2> 205013 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1438750551644831744)]} 0 1
[junit4:junit4] 2> 205024 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1438750551652171776)]} 0 1
[junit4:junit4] 2> 205025 T556 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!32 (1438750551652171776)]} 0 6
[junit4:junit4] 2> 205026 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32]} 0 10
[junit4:junit4] 2> 205030 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1438750551662657536)]} 0 1
[junit4:junit4] 2> 205041 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1438750551669997568)]} 0 1
[junit4:junit4] 2> 205042 T556 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!33 (1438750551669997568)]} 0 6
[junit4:junit4] 2> 205043 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33]} 0 10
[junit4:junit4] 2> 205047 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1438750551680483328)]} 0 1
[junit4:junit4] 2> 205059 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1438750551688871936)]} 0 1
[junit4:junit4] 2> 205060 T631 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!34 (1438750551688871936)]} 0 6
[junit4:junit4] 2> 205061 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34]} 0 10
[junit4:junit4] 2> 205065 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1438750551699357696)]} 0 1
[junit4:junit4] 2> 205073 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1438750551703552000)]} 0 1
[junit4:junit4] 2> 205074 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1438750551703552000)]} 0 6
[junit4:junit4] 2> 205078 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1438750551712989184)]} 0 1
[junit4:junit4] 2> 205086 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1438750551717183488)]} 0 1
[junit4:junit4] 2> 205087 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1438750551717183488)]} 0 6
[junit4:junit4] 2> 205091 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1438750551726620672)]} 0 1
[junit4:junit4] 2> 205103 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1438750551733960704)]} 0 2
[junit4:junit4] 2> 205103 T572 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58540/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1438750551733960704)]} 0 6
[junit4:junit4] 2> 205104 T590 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37]} 0 10
[junit4:junit4] 2> 205108 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1438750551744446464)]} 0 1
[junit4:junit4] 2> 205116 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1438750551748640768)]} 0 1
[junit4:junit4] 2> 205117 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1438750551748640768)]} 0 6
[junit4:junit4] 2> 205121 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1438750551758077952)]} 0 1
[junit4:junit4] 2> 205131 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1438750551763320832)]} 0 2
[junit4:junit4] 2> 205131 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1438750551763320832)]} 0 6
[junit4:junit4] 2> 205136 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1438750551773806592)]} 0 1
[junit4:junit4] 2> 205147 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1438750551781146624)]} 0 1
[junit4:junit4] 2> 205148 T576 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!40 (1438750551781146624)]} 0 6
[junit4:junit4] 2> 205149 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40]} 0 10
[junit4:junit4] 2> 205153 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1438750551791632384)]} 0 1
[junit4:junit4] 2> 205165 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1438750551800020992)]} 0 1
[junit4:junit4] 2> 205166 T558 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58540/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!41 (1438750551800020992)]} 0 6
[junit4:junit4] 2> 205167 T590 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41]} 0 10
[junit4:junit4] 2> 205171 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1438750551810506752)]} 0 1
[junit4:junit4] 2> 205180 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1438750551815749632)]} 0 1
[junit4:junit4] 2> 205181 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1438750551815749632)]} 0 6
[junit4:junit4] 2> 205185 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1438750551825186816)]} 0 1
[junit4:junit4] 2> 205194 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1438750551829381120)]} 0 2
[junit4:junit4] 2> 205194 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1438750551829381120)]} 0 6
[junit4:junit4] 2> 205199 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1438750551839866880)]} 0 1
[junit4:junit4] 2> 205210 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1438750551847206912)]} 0 1
[junit4:junit4] 2> 205211 T558 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58540/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!44 (1438750551847206912)]} 0 6
[junit4:junit4] 2> 205212 T590 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44]} 0 10
[junit4:junit4] 2> 205216 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1438750551857692672)]} 0 1
[junit4:junit4] 2> 205224 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1438750551861886976)]} 0 1
[junit4:junit4] 2> 205225 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1438750551861886976)]} 0 6
[junit4:junit4] 2> 205229 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1438750551871324160)]} 0 1
[junit4:junit4] 2> 205237 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1438750551875518464)]} 0 1
[junit4:junit4] 2> 205238 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1438750551875518464)]} 0 6
[junit4:junit4] 2> 205242 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1438750551884955648)]} 0 1
[junit4:junit4] 2> 205253 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1438750551892295680)]} 0 1
[junit4:junit4] 2> 205254 T631 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!47 (1438750551892295680)]} 0 6
[junit4:junit4] 2> 205255 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47]} 0 10
[junit4:junit4] 2> 205259 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1438750551902781440)]} 0 1
[junit4:junit4] 2> 205272 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1438750551911170048)]} 0 2
[junit4:junit4] 2> 205273 T556 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!48 (1438750551911170048)]} 0 7
[junit4:junit4] 2> 205273 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48]} 0 10
[junit4:junit4] 2> 205278 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1438750551922704384)]} 0 1
[junit4:junit4] 2> 205289 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1438750551930044416)]} 0 1
[junit4:junit4] 2> 205290 T578 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!49 (1438750551930044416)]} 0 6
[junit4:junit4] 2> 205291 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49]} 0 10
[junit4:junit4] 2> 205295 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1438750551940530176)]} 0 1
[junit4:junit4] 2> 205303 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1438750551944724480)]} 0 1
[junit4:junit4] 2> 205304 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1438750551944724480)]} 0 6
[junit4:junit4] 2> 205307 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1438750551952064512)]} 0 1
[junit4:junit4] 2> 205316 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1438750551957307392)]} 0 2
[junit4:junit4] 2> 205316 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1438750551957307392)]} 0 6
[junit4:junit4] 2> 205321 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1438750551967793152)]} 0 1
[junit4:junit4] 2> 205332 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1438750551975133184)]} 0 1
[junit4:junit4] 2> 205334 T576 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!52 (1438750551975133184)]} 0 7
[junit4:junit4] 2> 205334 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52]} 0 10
[junit4:junit4] 2> 205340 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1438750551986667520)]} 0 2
[junit4:junit4] 2> 205351 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1438750551995056128)]} 0 1
[junit4:junit4] 2> 205352 T558 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58540/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!53 (1438750551995056128)]} 0 6
[junit4:junit4] 2> 205353 T590 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53]} 0 10
[junit4:junit4] 2> 205357 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1438750552005541888)]} 0 1
[junit4:junit4] 2> 205369 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1438750552012881920)]} 0 2
[junit4:junit4] 2> 205369 T631 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!54 (1438750552012881920)]} 0 6
[junit4:junit4] 2> 205370 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54]} 0 10
[junit4:junit4] 2> 205375 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55 (1438750552024416256)]} 0 1
[junit4:junit4] 2> 205386 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1438750552031756288)]} 0 1
[junit4:junit4] 2> 205387 T576 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1438750552031756288)]} 0 6
[junit4:junit4] 2> 205388 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55]} 0 10
[junit4:junit4] 2> 205392 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1438750552042242048)]} 0 1
[junit4:junit4] 2> 205404 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1438750552050630656)]} 0 1
[junit4:junit4] 2> 205405 T572 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58540/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!56 (1438750552050630656)]} 0 6
[junit4:junit4] 2> 205406 T590 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56]} 0 10
[junit4:junit4] 2> 205410 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1438750552061116416)]} 0 1
[junit4:junit4] 2> 205421 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1438750552068456448)]} 0 1
[junit4:junit4] 2> 205422 T578 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!57 (1438750552068456448)]} 0 6
[junit4:junit4] 2> 205423 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57]} 0 10
[junit4:junit4] 2> 205427 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58 (1438750552078942208)]} 0 1
[junit4:junit4] 2> 205439 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1438750552087330816)]} 0 1
[junit4:junit4] 2> 205440 T556 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!58 (1438750552087330816)]} 0 6
[junit4:junit4] 2> 205441 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58]} 0 10
[junit4:junit4] 2> 205445 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1438750552097816576)]} 0 1
[junit4:junit4] 2> 205458 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1438750552106205184)]} 0 2
[junit4:junit4] 2> 205459 T631 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!59 (1438750552106205184)]} 0 7
[junit4:junit4] 2> 205460 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59]} 0 11
[junit4:junit4] 2> 205464 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1438750552117739520)]} 0 1
[junit4:junit4] 2> 205477 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1438750552126128128)]} 0 2
[junit4:junit4] 2> 205478 T556 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!60 (1438750552126128128)]} 0 7
[junit4:junit4] 2> 205479 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60]} 0 11
[junit4:junit4] 2> 205484 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1438750552137662464)]} 0 2
[junit4:junit4] 2> 205496 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1438750552146051072)]} 0 1
[junit4:junit4] 2> 205496 T556 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!61 (1438750552146051072)]} 0 6
[junit4:junit4] 2> 205498 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61]} 0 11
[junit4:junit4] 2> 205502 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62 (1438750552157585408)]} 0 1
[junit4:junit4] 2> 205515 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!62 (1438750552165974016)]} 0 1
[junit4:junit4] 2> 205517 T556 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!62 (1438750552165974016)]} 0 8
[junit4:junit4] 2> 205517 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62]} 0 11
[junit4:junit4] 2> 205522 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63 (1438750552178556928)]} 0 1
[junit4:junit4] 2> 205531 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!63 (1438750552183799808)]} 0 1
[junit4:junit4] 2> 205532 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63 (1438750552183799808)]} 0 6
[junit4:junit4] 2> 205536 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64 (1438750552193236992)]} 0 1
[junit4:junit4] 2> 205544 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!64 (1438750552197431296)]} 0 1
[junit4:junit4] 2> 205545 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64 (1438750552197431296)]} 0 6
[junit4:junit4] 2> 205549 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!65 (1438750552206868480)]} 0 1
[junit4:junit4] 2> 205561 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!65 (1438750552215257088)]} 0 1
[junit4:junit4] 2> 205562 T556 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58547/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!65 (1438750552215257088)]} 0 6
[junit4:junit4] 2> 205563 T608 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!65]} 0 10
[junit4:junit4] 2> 205567 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!66 (1438750552225742848)]} 0 1
[junit4:junit4] 2> 205579 T607 C141 P58547 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!66 (1438750552234131456)]} 0 1
[junit4:junit4] 2> 205580 T572 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58540/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!66 (1438750552234131456)]} 0 6
[junit4:junit4] 2> 205581 T590 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!66]} 0 10
[junit4:junit4] 2> 205585 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!67 (1438750552244617216)]} 0 1
[junit4:junit4] 2> 205596 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!67 (1438750552251957248)]} 0 1
[junit4:junit4] 2> 205597 T631 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58537/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!67 (1438750552251957248)]} 0 6
[junit4:junit4] 2> 205598 T574 C142 P58537 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!67]} 0 10
[junit4:junit4] 2> 205602 T536 C143 P58529 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!68 (1438750552262443008)]} 0 1
[junit4:junit4] 2> 205611 T588 C145 P58540 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58534/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!68 (1438750552267685888)]} 0 1
[junit4:junit4] 2> 205612 T560 C144 P58534 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!68 (1438750552267685888)]} 0 6
[junit4:junit4] 2> 205617 T536 C143 P58529 oasup.LogUpdateProcessor.finish
[...truncated too long message...]
[junit4:junit4] 2> 390788 T524 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 390841 T524 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 58547
[junit4:junit4] 2> 390841 T524 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1289688134
[junit4:junit4] 2> 391844 T524 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 391844 T524 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 391854 T524 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 391924 T524 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 391926 T524 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:58526 58526
[junit4:junit4] 2> 392050 T524 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 58529
[junit4:junit4] 2> !!!! WARNING: best effort to remove /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-1372099419797 FAILED !!!!!
[junit4:junit4] 2> 392051 T524 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 392052 T524 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:58526 58526
[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=B10E51C03F875E75 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_UY -Dtests.timezone=SystemV/EST5EDT -Dtests.file.encoding=US-ASCII
[junit4:junit4] ERROR 216s J0 | ShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:58534 returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([B10E51C03F875E75:30E8DFD848D83E49]: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> 392202 T524 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 419689 T615 oasu.PeerSync.handleResponse WARN PeerSync: core=collection1 url=http://127.0.0.1:58547 couldn't connect to http://127.0.0.1:58537/collection1/, counting as success
[junit4:junit4] 2> 419689 T615 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58547 DONE. sync succeeded
[junit4:junit4] 2> 419690 T615 oasc.SyncStrategy.syncReplicas We have been closed, won't attempt to sync replicas back to leader
[junit4:junit4] 2> 419691 T615 oasc.ShardLeaderElectionContext.rejoinLeaderElection Not rejoining election because CoreContainer is shutdown
[junit4:junit4] 2> 419691 T615 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@63e78458
[junit4:junit4] 2> 419701 T615 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=2,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=706,adds=706,deletesById=354,deletesByQuery=0,errors=0,cumulative_adds=748,cumulative_deletesById=354,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 419702 T615 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 419702 T615 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 419702 T615 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 419732 T615 C251 P58547 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@612baafc lockFactory=org.apache.lucene.store.NativeFSLockFactory@38756f7f),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@612baafc lockFactory=org.apache.lucene.store.NativeFSLockFactory@38756f7f),segFN=segments_5,generation=5}
[junit4:junit4] 2> 419733 T615 C251 P58547 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 419737 T615 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 419738 T615 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 419738 T615 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4/index;done=false>>]
[junit4:junit4] 2> 419738 T615 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4/index
[junit4:junit4] 2> 419739 T615 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4;done=false>>]
[junit4:junit4] 2> 419739 T615 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372099419797/jetty4
[junit4:junit4] 2> 419739 T615 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> 419739 T615 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 419740 T615 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 419740 T615 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> 419740 T615 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 419740 T615 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=PostingsFormat(name=Direct), _version_=PostingsFormat(name=NestedPulsing), n_ti=PostingsFormat(name=TestBloomFilteredLucene41Postings)}, docValues:{}, sim=DefaultSimilarity, locale=es_UY, timezone=SystemV/EST5EDT
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=2,free=48325960,total=165675008
[junit4:junit4] 2> NOTE: All tests run in this JVM: [FastVectorHighlighterTest, BinaryUpdateRequestHandlerTest, ShardRoutingTest, SystemInfoHandlerTest, TestCloudManagedSchemaAddField, TestBadConfig, PreAnalyzedUpdateProcessorTest, ShardSplitTest]
[junit4:junit4] Completed on J0 in 244.30s, 1 test, 1 error <<< FAILURES!
[...truncated 847 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:386: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:366: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/lucene/common-build.xml:887: There were test failures: 297 suites, 1253 tests, 1 error, 13 ignored (7 assumptions)
Total time: 51 minutes 34 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure