You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/24 16:13:11 UTC
[JENKINS] Lucene-Solr-trunk-MacOSX (64bit/jdk1.7.0) - Build # 591 -
Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-MacOSX/591/
Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseParallelGC
1 tests failed.
FAILED: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:49835/un/r 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:49835/un/r returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([B19E8151CB3CD84D:30780F49BC63B871]: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:606)
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:724)
Build Log:
[...truncated 9448 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 1337851 T2672 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /un/r
[junit4:junit4] 2> 1337857 T2672 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./solrtest-ShardSplitTest-1372080948807
[junit4:junit4] 2> 1337859 T2672 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1337861 T2673 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1337973 T2672 oasc.ZkTestServer.run start zk server on port:49828
[junit4:junit4] 2> 1337980 T2672 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1337986 T2679 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@58b977c7 name:ZooKeeperConnection Watcher:127.0.0.1:49828 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1337986 T2672 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1337987 T2672 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1338001 T2672 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1338007 T2681 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@22864d3e name:ZooKeeperConnection Watcher:127.0.0.1:49828/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1338007 T2672 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1338007 T2672 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1338023 T2672 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1338030 T2672 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1338036 T2672 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1338043 T2672 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1338044 T2672 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1338054 T2672 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 1338055 T2672 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1338062 T2672 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1338062 T2672 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1338074 T2672 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 1338075 T2672 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1338086 T2672 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 1338088 T2672 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1338095 T2672 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1338096 T2672 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1338106 T2672 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1338107 T2672 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1338115 T2672 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1338116 T2672 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1338124 T2672 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1338125 T2672 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1338681 T2672 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1338702 T2672 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49831
[junit4:junit4] 2> 1338703 T2672 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1338704 T2672 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1338704 T2672 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372080949082
[junit4:junit4] 2> 1338704 T2672 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372080949082/solr.xml
[junit4:junit4] 2> 1338705 T2672 oasc.CoreContainer.<init> New CoreContainer 999809992
[junit4:junit4] 2> 1338706 T2672 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372080949082/'
[junit4:junit4] 2> 1338706 T2672 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372080949082/'
[junit4:junit4] 2> 1338898 T2672 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1338899 T2672 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1338900 T2672 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1338900 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1338901 T2672 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1338901 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1338901 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1338902 T2672 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1338902 T2672 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1338903 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1338932 T2672 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1338934 T2672 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49828/solr
[junit4:junit4] 2> 1338935 T2672 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1338940 T2672 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1339342 T2692 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2cd7ade0 name:ZooKeeperConnection Watcher:127.0.0.1:49828 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1339348 T2672 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1340168 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1340198 T2672 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1340207 T2694 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3fd00db1 name:ZooKeeperConnection Watcher:127.0.0.1:49828/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1340207 T2672 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1340224 T2672 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1340276 T2672 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1340302 T2672 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1340311 T2672 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49831_un%2Fr
[junit4:junit4] 2> 1340314 T2672 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49831_un%2Fr
[junit4:junit4] 2> 1340328 T2672 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1340361 T2672 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1340373 T2672 oasc.Overseer.start Overseer (id=89920697061605379-127.0.0.1:49831_un%2Fr-n_0000000000) starting
[junit4:junit4] 2> 1340388 T2672 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1340465 T2696 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1340468 T2672 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1340484 T2672 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1340491 T2672 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1340508 T2697 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1340509 T2697 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1340509 T2695 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1340521 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1340523 T2695 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49831_un%2Fr",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49831/un/r"}
[junit4:junit4] 2> 1340523 T2695 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1340524 T2695 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1340544 T2694 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> 1341515 T2697 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372080949082/collection1
[junit4:junit4] 2> 1341516 T2697 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1341518 T2697 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1341518 T2697 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1341524 T2697 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372080949082/collection1/'
[junit4:junit4] 2> 1341526 T2697 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1372080949082/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1341527 T2697 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1372080949082/collection1/lib/README' to classloader
[junit4:junit4] 2> 1341644 T2697 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1341800 T2697 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1341806 T2697 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1341819 T2697 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1342867 T2697 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1342872 T2697 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1342874 T2697 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1342881 T2697 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1342958 T2697 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1342958 T2697 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1372080949082/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372080948806/control/data/
[junit4:junit4] 2> 1342959 T2697 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2bfabe2a
[junit4:junit4] 2> 1342960 T2697 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1342961 T2697 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372080948806/control/data
[junit4:junit4] 2> 1342962 T2697 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372080948806/control/data/index/
[junit4:junit4] 2> 1342962 T2697 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372080948806/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1342963 T2697 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372080948806/control/data/index
[junit4:junit4] 2> 1342969 T2697 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@698b7f01 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a0a6710),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1342969 T2697 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1342973 T2697 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1342973 T2697 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1342974 T2697 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1342975 T2697 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1342976 T2697 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1342976 T2697 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1342976 T2697 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1342978 T2697 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1342978 T2697 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1343000 T2697 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1343010 T2697 oass.SolrIndexSearcher.<init> Opening Searcher@6a99007b main
[junit4:junit4] 2> 1343010 T2697 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372080948806/control/data/tlog
[junit4:junit4] 2> 1343012 T2697 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1343012 T2697 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1343016 T2698 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6a99007b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1343017 T2697 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1343017 T2697 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49831/un/r collection:control_collection shard:shard1
[junit4:junit4] 2> 1343019 T2697 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1343043 T2697 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1343050 T2697 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1343050 T2697 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1343050 T2697 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49831/un/r/collection1/
[junit4:junit4] 2> 1343051 T2697 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1343051 T2697 oasc.SyncStrategy.syncToMe http://127.0.0.1:49831/un/r/collection1/ has no replicas
[junit4:junit4] 2> 1343051 T2697 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49831/un/r/collection1/
[junit4:junit4] 2> 1343051 T2697 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1343566 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1343585 T2694 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> 1343635 T2697 oasc.ZkController.register We are http://127.0.0.1:49831/un/r/collection1/ and leader is http://127.0.0.1:49831/un/r/collection1/
[junit4:junit4] 2> 1343635 T2697 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49831/un/r
[junit4:junit4] 2> 1343636 T2697 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1343636 T2697 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1343636 T2697 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1343640 T2697 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1343643 T2672 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1343644 T2672 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1343645 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1343672 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1343682 T2672 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1343688 T2701 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f82047 name:ZooKeeperConnection Watcher:127.0.0.1:49828/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1343691 T2672 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1343696 T2672 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1343704 T2672 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1344391 T2672 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1344406 T2672 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49835
[junit4:junit4] 2> 1344407 T2672 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1344408 T2672 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1344409 T2672 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372080954653
[junit4:junit4] 2> 1344410 T2672 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372080954653/solr.xml
[junit4:junit4] 2> 1344410 T2672 oasc.CoreContainer.<init> New CoreContainer 310232951
[junit4:junit4] 2> 1344411 T2672 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372080954653/'
[junit4:junit4] 2> 1344416 T2672 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372080954653/'
[junit4:junit4] 2> 1344602 T2672 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1344603 T2672 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1344603 T2672 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1344604 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1344604 T2672 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1344605 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1344605 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1344606 T2672 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1344606 T2672 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1344607 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1344630 T2672 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1344637 T2672 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49828/solr
[junit4:junit4] 2> 1344638 T2672 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1344640 T2672 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1344649 T2712 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3d1efd6e name:ZooKeeperConnection Watcher:127.0.0.1:49828 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1344650 T2672 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1344657 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1344682 T2672 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1344701 T2714 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1cadc82c name:ZooKeeperConnection Watcher:127.0.0.1:49828/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1344702 T2672 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1344717 T2672 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1345103 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1345105 T2695 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:49831_un%2Fr_collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49831_un%2Fr",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49831/un/r"}
[junit4:junit4] 2> 1345119 T2701 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> 1345120 T2694 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> 1345120 T2714 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> 1345733 T2672 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49835_un%2Fr
[junit4:junit4] 2> 1345735 T2672 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49835_un%2Fr
[junit4:junit4] 2> 1345741 T2701 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 1345745 T2714 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1345745 T2714 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> 1345749 T2694 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 1345753 T2701 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1345760 T2694 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1345770 T2715 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1345770 T2715 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1346655 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1346657 T2695 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49835_un%2Fr",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49835/un/r"}
[junit4:junit4] 2> 1346658 T2695 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 1346658 T2695 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1346695 T2701 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> 1346696 T2714 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> 1346696 T2694 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> 1346782 T2715 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372080954653/collection1
[junit4:junit4] 2> 1346783 T2715 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1346785 T2715 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1346785 T2715 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1346792 T2715 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372080954653/collection1/'
[junit4:junit4] 2> 1346794 T2715 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1372080954653/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1346795 T2715 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1372080954653/collection1/lib/README' to classloader
[junit4:junit4] 2> 1347032 T2715 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1347202 T2715 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1347213 T2715 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1347219 T2715 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1348203 T2715 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1348212 T2715 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1348220 T2715 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1348231 T2715 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1348317 T2715 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1348318 T2715 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1372080954653/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty1/
[junit4:junit4] 2> 1348318 T2715 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2bfabe2a
[junit4:junit4] 2> 1348319 T2715 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1348320 T2715 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty1
[junit4:junit4] 2> 1348321 T2715 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty1/index/
[junit4:junit4] 2> 1348321 T2715 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1348322 T2715 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty1/index
[junit4:junit4] 2> 1348328 T2715 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@25b0532 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f2aa497),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1348328 T2715 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1348341 T2715 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1348344 T2715 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1348345 T2715 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1348347 T2715 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1348350 T2715 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1348351 T2715 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1348352 T2715 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1348353 T2715 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1348354 T2715 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1348383 T2715 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1348419 T2715 oass.SolrIndexSearcher.<init> Opening Searcher@2c3d450e main
[junit4:junit4] 2> 1348420 T2715 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty1/tlog
[junit4:junit4] 2> 1348424 T2715 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1348424 T2715 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1348442 T2716 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2c3d450e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1348443 T2715 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1348443 T2715 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49835/un/r collection:collection1 shard:shard1
[junit4:junit4] 2> 1348445 T2715 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1348645 T2715 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1348656 T2715 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1348656 T2715 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1348656 T2715 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49835/un/r/collection1/
[junit4:junit4] 2> 1348657 T2715 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1348657 T2715 oasc.SyncStrategy.syncToMe http://127.0.0.1:49835/un/r/collection1/ has no replicas
[junit4:junit4] 2> 1348657 T2715 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49835/un/r/collection1/
[junit4:junit4] 2> 1348658 T2715 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1349730 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1349763 T2701 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> 1349763 T2694 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> 1349766 T2714 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> 1349800 T2715 oasc.ZkController.register We are http://127.0.0.1:49835/un/r/collection1/ and leader is http://127.0.0.1:49835/un/r/collection1/
[junit4:junit4] 2> 1349801 T2715 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49835/un/r
[junit4:junit4] 2> 1349801 T2715 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1349801 T2715 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1349802 T2715 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1349807 T2715 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1349812 T2672 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1349813 T2672 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1349813 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1350451 T2672 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1350459 T2672 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49838
[junit4:junit4] 2> 1350461 T2672 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1350461 T2672 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1350462 T2672 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372080960786
[junit4:junit4] 2> 1350463 T2672 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372080960786/solr.xml
[junit4:junit4] 2> 1350464 T2672 oasc.CoreContainer.<init> New CoreContainer 156076619
[junit4:junit4] 2> 1350465 T2672 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372080960786/'
[junit4:junit4] 2> 1350465 T2672 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372080960786/'
[junit4:junit4] 2> 1350692 T2672 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1350693 T2672 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1350694 T2672 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1350695 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1350695 T2672 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1350705 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1350705 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1350706 T2672 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1350706 T2672 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1350707 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1350727 T2672 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1350729 T2672 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49828/solr
[junit4:junit4] 2> 1350730 T2672 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1350735 T2672 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1350741 T2728 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@254a4bad name:ZooKeeperConnection Watcher:127.0.0.1:49828 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1350742 T2672 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1350748 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1350786 T2672 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1350791 T2730 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c99d6d6 name:ZooKeeperConnection Watcher:127.0.0.1:49828/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1350792 T2672 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1350819 T2672 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1351307 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1351318 T2695 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:49835_un%2Fr_collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49835_un%2Fr",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49835/un/r"}
[junit4:junit4] 2> 1351350 T2694 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> 1351350 T2701 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> 1351351 T2714 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> 1351350 T2730 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> 1351834 T2672 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49838_un%2Fr
[junit4:junit4] 2> 1351837 T2672 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49838_un%2Fr
[junit4:junit4] 2> 1351845 T2701 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> 1351846 T2694 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> 1351849 T2730 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1351850 T2730 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> 1351850 T2714 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1351851 T2714 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> 1351856 T2701 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1351856 T2694 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1351912 T2731 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1351912 T2731 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1352926 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1352928 T2695 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49838_un%2Fr",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49838/un/r"}
[junit4:junit4] 2> 1352928 T2695 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1352929 T2695 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1352959 T2701 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> 1352960 T2730 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> 1352960 T2714 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> 1352960 T2694 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> 1353929 T2731 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372080960786/collection1
[junit4:junit4] 2> 1353930 T2731 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1353934 T2731 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1353935 T2731 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1353939 T2731 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372080960786/collection1/'
[junit4:junit4] 2> 1353941 T2731 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1372080960786/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1353942 T2731 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1372080960786/collection1/lib/README' to classloader
[junit4:junit4] 2> 1354047 T2731 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1354141 T2731 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1354158 T2731 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1354166 T2731 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1355368 T2731 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1355376 T2731 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1355379 T2731 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1355424 T2731 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1355680 T2731 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1355681 T2731 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1372080960786/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty2/
[junit4:junit4] 2> 1355681 T2731 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2bfabe2a
[junit4:junit4] 2> 1355681 T2731 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1355691 T2731 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty2
[junit4:junit4] 2> 1355703 T2731 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty2/index/
[junit4:junit4] 2> 1355706 T2731 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1355713 T2731 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty2/index
[junit4:junit4] 2> 1355718 T2731 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18d55090 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8a5a8fe),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1355719 T2731 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1355726 T2731 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1355726 T2731 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1355728 T2731 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1355729 T2731 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1355730 T2731 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1355731 T2731 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1355731 T2731 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1355732 T2731 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1355733 T2731 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1355755 T2731 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1355785 T2731 oass.SolrIndexSearcher.<init> Opening Searcher@2b806f28 main
[junit4:junit4] 2> 1355786 T2731 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty2/tlog
[junit4:junit4] 2> 1355787 T2731 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1355788 T2731 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1355794 T2732 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2b806f28 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1355801 T2731 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1355801 T2731 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49838/un/r collection:collection1 shard:shard2
[junit4:junit4] 2> 1355813 T2731 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 1355899 T2731 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1355915 T2731 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1355915 T2731 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1355916 T2731 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49838/un/r/collection1/
[junit4:junit4] 2> 1355916 T2731 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1355916 T2731 oasc.SyncStrategy.syncToMe http://127.0.0.1:49838/un/r/collection1/ has no replicas
[junit4:junit4] 2> 1355917 T2731 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49838/un/r/collection1/
[junit4:junit4] 2> 1355917 T2731 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1356007 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1356097 T2701 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> 1356098 T2714 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> 1356098 T2694 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> 1356097 T2730 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> 1356148 T2731 oasc.ZkController.register We are http://127.0.0.1:49838/un/r/collection1/ and leader is http://127.0.0.1:49838/un/r/collection1/
[junit4:junit4] 2> 1356148 T2731 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49838/un/r
[junit4:junit4] 2> 1356148 T2731 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1356149 T2731 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1356149 T2731 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1356180 T2731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1356206 T2672 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1356206 T2672 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1356208 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1356942 T2672 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1356954 T2672 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49841
[junit4:junit4] 2> 1356955 T2672 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1356955 T2672 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1356957 T2672 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372080967193
[junit4:junit4] 2> 1356957 T2672 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372080967193/solr.xml
[junit4:junit4] 2> 1356958 T2672 oasc.CoreContainer.<init> New CoreContainer 1543720426
[junit4:junit4] 2> 1356959 T2672 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372080967193/'
[junit4:junit4] 2> 1356962 T2672 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372080967193/'
[junit4:junit4] 2> 1357193 T2672 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1357194 T2672 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1357195 T2672 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1357195 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1357196 T2672 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1357196 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1357197 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1357197 T2672 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1357198 T2672 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1357198 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1357232 T2672 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1357233 T2672 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49828/solr
[junit4:junit4] 2> 1357234 T2672 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1357245 T2672 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1357255 T2744 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@576c3468 name:ZooKeeperConnection Watcher:127.0.0.1:49828 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1357256 T2672 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1357267 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1357298 T2672 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1357304 T2746 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7d40f6ec name:ZooKeeperConnection Watcher:127.0.0.1:49828/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1357310 T2672 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1357345 T2672 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1357656 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1357658 T2695 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:49838_un%2Fr_collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49838_un%2Fr",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49838/un/r"}
[junit4:junit4] 2> 1357685 T2701 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> 1357685 T2714 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> 1357686 T2746 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> 1357686 T2694 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> 1357686 T2730 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> 1358373 T2672 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49841_un%2Fr
[junit4:junit4] 2> 1358378 T2672 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49841_un%2Fr
[junit4:junit4] 2> 1358386 T2701 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> 1358387 T2694 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> 1358388 T2746 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> 1358390 T2714 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1358390 T2714 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> 1358391 T2730 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1358391 T2730 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> 1358398 T2701 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1358398 T2694 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1358399 T2746 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1358415 T2747 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1358416 T2747 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1359208 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1359213 T2695 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49841_un%2Fr",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49841/un/r"}
[junit4:junit4] 2> 1359213 T2695 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1359213 T2695 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1359242 T2701 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> 1359243 T2730 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> 1359243 T2714 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> 1359243 T2746 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> 1359245 T2694 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> 1359420 T2747 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372080967193/collection1
[junit4:junit4] 2> 1359420 T2747 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1359424 T2747 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1359424 T2747 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1359431 T2747 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372080967193/collection1/'
[junit4:junit4] 2> 1359435 T2747 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1372080967193/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1359435 T2747 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1372080967193/collection1/lib/README' to classloader
[junit4:junit4] 2> 1359521 T2747 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1359621 T2747 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1359626 T2747 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1359636 T2747 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1360673 T2747 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1360687 T2747 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1360690 T2747 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1360702 T2747 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1360947 T2747 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1360947 T2747 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1372080967193/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty3/
[junit4:junit4] 2> 1360948 T2747 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2bfabe2a
[junit4:junit4] 2> 1360949 T2747 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1360953 T2747 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty3
[junit4:junit4] 2> 1360955 T2747 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty3/index/
[junit4:junit4] 2> 1360955 T2747 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1360957 T2747 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty3/index
[junit4:junit4] 2> 1360980 T2747 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c0fbc41 lockFactory=org.apache.lucene.store.NativeFSLockFactory@37c2317f),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1360980 T2747 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1360988 T2747 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1360988 T2747 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1360989 T2747 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1360990 T2747 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1360991 T2747 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1360991 T2747 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1360992 T2747 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1360993 T2747 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1360994 T2747 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1361015 T2747 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1361037 T2747 oass.SolrIndexSearcher.<init> Opening Searcher@6afbd71f main
[junit4:junit4] 2> 1361038 T2747 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty3/tlog
[junit4:junit4] 2> 1361040 T2747 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1361042 T2747 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1361053 T2748 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6afbd71f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1361061 T2747 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1361062 T2747 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49841/un/r collection:collection1 shard:shard1
[junit4:junit4] 2> 1361080 T2747 oasc.ZkController.register We are http://127.0.0.1:49841/un/r/collection1/ and leader is http://127.0.0.1:49835/un/r/collection1/
[junit4:junit4] 2> 1361080 T2747 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49841/un/r
[junit4:junit4] 2> 1361080 T2747 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1361081 T2747 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C554 name=collection1 org.apache.solr.core.SolrCore@6b3f6000 url=http://127.0.0.1:49841/un/r/collection1 node=127.0.0.1:49841_un%2Fr C554_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:49841_un%2Fr, base_url=http://127.0.0.1:49841/un/r}
[junit4:junit4] 2> 1361082 T2749 C554 P49841 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1361084 T2749 C554 P49841 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1361084 T2749 C554 P49841 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1361085 T2749 C554 P49841 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1361092 T2747 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1361094 T2749 C554 P49841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1361105 T2672 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1361106 T2672 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1361106 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1361119 T2708 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:49841_un%2Fr_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1361904 T2672 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1361914 T2672 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49845
[junit4:junit4] 2> 1361916 T2672 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1361917 T2672 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1361918 T2672 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372080972071
[junit4:junit4] 2> 1361918 T2672 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372080972071/solr.xml
[junit4:junit4] 2> 1361919 T2672 oasc.CoreContainer.<init> New CoreContainer 770397955
[junit4:junit4] 2> 1361920 T2672 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372080972071/'
[junit4:junit4] 2> 1361925 T2672 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372080972071/'
[junit4:junit4] 2> 1362138 T2672 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1362139 T2672 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1362139 T2672 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1362140 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1362140 T2672 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1362141 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1362144 T2672 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1362145 T2672 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1362145 T2672 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1362146 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1362187 T2672 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1362188 T2672 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49828/solr
[junit4:junit4] 2> 1362188 T2672 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1362191 T2672 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1362197 T2761 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@65d8ecf3 name:ZooKeeperConnection Watcher:127.0.0.1:49828 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1362198 T2672 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1362249 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1362275 T2672 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1362282 T2763 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@423e74ea name:ZooKeeperConnection Watcher:127.0.0.1:49828/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1362282 T2672 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1362293 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1362295 T2695 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:49841_un%2Fr_collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49841_un%2Fr",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49841/un/r"}
[junit4:junit4] 2> 1362318 T2701 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> 1362318 T2730 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> 1362318 T2714 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> 1362319 T2694 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> 1362319 T2746 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> 1362342 T2672 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1363122 T2708 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:49841_un%2Fr_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1363126 T2708 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:49841_un%252Fr_collection1&state=recovering&nodeName=127.0.0.1:49841_un%252Fr&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2007
[junit4:junit4] 2> 1363357 T2672 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49845_un%2Fr
[junit4:junit4] 2> 1363359 T2672 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49845_un%2Fr
[junit4:junit4] 2> 1363367 T2701 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> 1363367 T2694 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> 1363367 T2746 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> 1363372 T2714 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1363373 T2714 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> 1363373 T2730 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1363373 T2730 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> 1363374 T2763 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1363379 T2701 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1363379 T2694 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1363380 T2746 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1363395 T2764 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1363395 T2764 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1363851 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1363854 T2695 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49845_un%2Fr",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49845/un/r"}
[junit4:junit4] 2> 1363854 T2695 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1363854 T2695 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1363875 T2701 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> 1363876 T2694 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> 1363877 T2714 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> 1363877 T2730 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> 1363877 T2746 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> 1363877 T2763 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> 1364404 T2764 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372080972071/collection1
[junit4:junit4] 2> 1364405 T2764 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1364409 T2764 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1364409 T2764 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1364421 T2764 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372080972071/collection1/'
[junit4:junit4] 2> 1364425 T2764 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1372080972071/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1364426 T2764 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1372080972071/collection1/lib/README' to classloader
[junit4:junit4] 2> 1364495 T2764 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1364587 T2764 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1364590 T2764 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1364598 T2764 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C555 name=collection1 org.apache.solr.core.SolrCore@6b3f6000 url=http://127.0.0.1:49841/un/r/collection1 node=127.0.0.1:49841_un%2Fr C555_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:49841_un%2Fr, base_url=http://127.0.0.1:49841/un/r}
[junit4:junit4] 2> 1365128 T2749 C555 P49841 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49835/un/r/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1365129 T2749 C555 P49841 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49841/un/r START replicas=[http://127.0.0.1:49835/un/r/collection1/] nUpdates=100
[junit4:junit4] 2> 1365131 T2749 C555 P49841 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1365133 T2749 C555 P49841 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1365133 T2749 C555 P49841 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1365133 T2749 C555 P49841 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1365134 T2749 C555 P49841 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1365134 T2749 C555 P49841 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49835/un/r/collection1/. core=collection1
[junit4:junit4] 2> 1365134 T2749 C555 P49841 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C556 name=collection1 org.apache.solr.core.SolrCore@6553bb66 url=http://127.0.0.1:49835/un/r/collection1 node=127.0.0.1:49835_un%2Fr C556_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49835_un%2Fr, base_url=http://127.0.0.1:49835/un/r, leader=true}
[junit4:junit4] 2> 1365185 T2709 C556 P49835 oasc.SolrCore.execute [collection1] webapp=/un/r path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=11
[junit4:junit4] 2> 1365189 T2710 C556 P49835 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1365205 T2710 C556 P49835 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@25b0532 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f2aa497),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1365227 T2710 C556 P49835 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1365229 T2710 C556 P49835 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@25b0532 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f2aa497),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@25b0532 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f2aa497),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1365229 T2710 C556 P49835 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1365236 T2710 C556 P49835 oass.SolrIndexSearcher.<init> Opening Searcher@557f8c5a realtime
[junit4:junit4] 2> 1365237 T2710 C556 P49835 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1365238 T2710 C556 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 49
[junit4:junit4] 2> 1365241 T2749 C555 P49841 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1365242 T2749 C555 P49841 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1365263 T2706 C556 P49835 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1365264 T2706 C556 P49835 oasc.SolrCore.execute [collection1] webapp=/un/r path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=10
[junit4:junit4] 2> 1365266 T2749 C555 P49841 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1365266 T2749 C555 P49841 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1365266 T2749 C555 P49841 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1365278 T2707 C556 P49835 oasc.SolrCore.execute [collection1] webapp=/un/r path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=4
[junit4:junit4] 2> 1365279 T2749 C555 P49841 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1365281 T2749 C555 P49841 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty3/index.20130624213616227
[junit4:junit4] 2> 1365282 T2749 C555 P49841 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@4520c1d9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@415ce082) fullCopy=false
[junit4:junit4] 2> 1365287 T2708 C556 P49835 oasc.SolrCore.execute [collection1] webapp=/un/r path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1365298 T2749 C555 P49841 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1365315 T2749 C555 P49841 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1365315 T2749 C555 P49841 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1365319 T2749 C555 P49841 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c0fbc41 lockFactory=org.apache.lucene.store.NativeFSLockFactory@37c2317f),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c0fbc41 lockFactory=org.apache.lucene.store.NativeFSLockFactory@37c2317f),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1365329 T2749 C555 P49841 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1365330 T2749 C555 P49841 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1365331 T2749 C555 P49841 oass.SolrIndexSearcher.<init> Opening Searcher@3a89340a main
[junit4:junit4] 2> 1365332 T2748 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3a89340a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1365333 T2749 C555 P49841 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty3/index.20130624213616227 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty3/index.20130624213616227;done=true>>]
[junit4:junit4] 2> 1365334 T2749 C555 P49841 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty3/index.20130624213616227
[junit4:junit4] 2> 1365334 T2749 C555 P49841 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty3/index.20130624213616227
[junit4:junit4] 2> 1365334 T2749 C555 P49841 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1365334 T2749 C555 P49841 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1365335 T2749 C555 P49841 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1365335 T2749 C555 P49841 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1365340 T2749 C555 P49841 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1365404 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1365406 T2695 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:49841_un%2Fr_collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49841_un%2Fr",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49841/un/r"}
[junit4:junit4] 2> 1365419 T2701 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> 1365420 T2694 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> 1365420 T2746 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> 1365420 T2763 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> 1365421 T2730 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> 1365421 T2714 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> 1365620 T2764 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1365625 T2764 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1365627 T2764 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1365637 T2764 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1365711 T2764 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1365711 T2764 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1372080972071/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4/
[junit4:junit4] 2> 1365712 T2764 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2bfabe2a
[junit4:junit4] 2> 1365713 T2764 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1365714 T2764 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4
[junit4:junit4] 2> 1365714 T2764 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4/index/
[junit4:junit4] 2> 1365714 T2764 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1365716 T2764 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4/index
[junit4:junit4] 2> 1365719 T2764 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@31abb139 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2ae290c6),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1365720 T2764 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1365724 T2764 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1365725 T2764 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1365726 T2764 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1365727 T2764 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1365728 T2764 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1365728 T2764 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1365731 T2764 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1365733 T2764 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1365733 T2764 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1365760 T2764 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1365768 T2764 oass.SolrIndexSearcher.<init> Opening Searcher@3ff02225 main
[junit4:junit4] 2> 1365769 T2764 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4/tlog
[junit4:junit4] 2> 1365771 T2764 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1365771 T2764 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1365783 T2767 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3ff02225 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1365788 T2764 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1365788 T2764 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49845/un/r collection:collection1 shard:shard2
[junit4:junit4] 2> 1365796 T2764 oasc.ZkController.register We are http://127.0.0.1:49845/un/r/collection1/ and leader is http://127.0.0.1:49838/un/r/collection1/
[junit4:junit4] 2> 1365796 T2764 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49845/un/r
[junit4:junit4] 2> 1365797 T2764 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1365797 T2764 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C557 name=collection1 org.apache.solr.core.SolrCore@32ddf8cc url=http://127.0.0.1:49845/un/r/collection1 node=127.0.0.1:49845_un%2Fr C557_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:49845_un%2Fr, base_url=http://127.0.0.1:49845/un/r}
[junit4:junit4] 2> 1365798 T2768 C557 P49845 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1365799 T2768 C557 P49845 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1365800 T2768 C557 P49845 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1365800 T2768 C557 P49845 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1365801 T2764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1365803 T2768 C557 P49845 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1365825 T2672 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1365827 T2672 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1365828 T2672 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1365841 T2721 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:49845_un%2Fr_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1365853 T2672 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1365855 T2672 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 1365857 T2672 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 1365859 T2672 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1366863 T2672 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1366941 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1366944 T2695 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:49845_un%2Fr_collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49845_un%2Fr",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49845/un/r"}
[junit4:junit4] 2> 1366958 T2694 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> 1366959 T2746 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> 1366959 T2714 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> 1366960 T2730 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> 1366973 T2701 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> 1366974 T2763 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> 1367852 T2721 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:49845_un%2Fr_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1367853 T2721 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:49845_un%252Fr_collection1&state=recovering&nodeName=127.0.0.1:49845_un%252Fr&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2012
[junit4:junit4] 2> 1367868 T2672 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1368873 T2672 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C557_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:49845_un%2Fr, base_url=http://127.0.0.1:49845/un/r}
[junit4:junit4] 2> 1369855 T2768 C557 P49845 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49838/un/r/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1369856 T2768 C557 P49845 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49845/un/r START replicas=[http://127.0.0.1:49838/un/r/collection1/] nUpdates=100
[junit4:junit4] 2> 1369857 T2768 C557 P49845 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1369857 T2768 C557 P49845 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1369857 T2768 C557 P49845 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1369857 T2768 C557 P49845 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1369858 T2768 C557 P49845 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1369858 T2768 C557 P49845 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49838/un/r/collection1/. core=collection1
[junit4:junit4] 2> 1369858 T2768 C557 P49845 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1369882 T2672 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C558 name=collection1 org.apache.solr.core.SolrCore@5f0f46d6 url=http://127.0.0.1:49838/un/r/collection1 node=127.0.0.1:49838_un%2Fr C558_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49838_un%2Fr, base_url=http://127.0.0.1:49838/un/r, leader=true}
[junit4:junit4] 2> 1369893 T2721 C558 P49838 oasc.SolrCore.execute [collection1] webapp=/un/r path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=2
[junit4:junit4] 2> 1369897 T2724 C558 P49838 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1369901 T2724 C558 P49838 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18d55090 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8a5a8fe),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1369901 T2724 C558 P49838 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1369902 T2724 C558 P49838 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18d55090 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8a5a8fe),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18d55090 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8a5a8fe),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1369903 T2724 C558 P49838 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1369904 T2724 C558 P49838 oass.SolrIndexSearcher.<init> Opening Searcher@24496446 realtime
[junit4:junit4] 2> 1369904 T2724 C558 P49838 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1369904 T2724 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 1369906 T2768 C557 P49845 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1369906 T2768 C557 P49845 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1369911 T2725 C558 P49838 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1369912 T2725 C558 P49838 oasc.SolrCore.execute [collection1] webapp=/un/r path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 1369913 T2768 C557 P49845 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1369913 T2768 C557 P49845 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1369913 T2768 C557 P49845 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1369917 T2726 C558 P49838 oasc.SolrCore.execute [collection1] webapp=/un/r path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 1369921 T2768 C557 P49845 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1369930 T2768 C557 P49845 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4/index.20130624213620872
[junit4:junit4] 2> 1369930 T2768 C557 P49845 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@43b6586b lockFactory=org.apache.lucene.store.NativeFSLockFactory@709fc325) fullCopy=false
[junit4:junit4] 2> 1369937 T2721 C558 P49838 oasc.SolrCore.execute [collection1] webapp=/un/r path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1369939 T2768 C557 P49845 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1369941 T2768 C557 P49845 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1369941 T2768 C557 P49845 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1369944 T2768 C557 P49845 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@31abb139 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2ae290c6),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@31abb139 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2ae290c6),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1369944 T2768 C557 P49845 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1369945 T2768 C557 P49845 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1369945 T2768 C557 P49845 oass.SolrIndexSearcher.<init> Opening Searcher@55687b84 main
[junit4:junit4] 2> 1369947 T2767 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@55687b84 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1369947 T2768 C557 P49845 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4/index.20130624213620872 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4/index.20130624213620872;done=true>>]
[junit4:junit4] 2> 1369948 T2768 C557 P49845 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4/index.20130624213620872
[junit4:junit4] 2> 1369948 T2768 C557 P49845 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4/index.20130624213620872
[junit4:junit4] 2> 1369948 T2768 C557 P49845 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1369949 T2768 C557 P49845 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1369949 T2768 C557 P49845 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1369949 T2768 C557 P49845 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1369951 T2768 C557 P49845 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1369991 T2695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1369996 T2695 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:49845_un%2Fr_collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49845_un%2Fr",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49845/un/r"}
[junit4:junit4] 2> 1370009 T2694 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> 1370010 T2746 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> 1370010 T2763 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> 1370011 T2730 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> 1370011 T2714 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> 1370025 T2701 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> 1370887 T2672 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1370889 T2672 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C559 name=collection1 org.apache.solr.core.SolrCore@16a7f771 url=http://127.0.0.1:49831/un/r/collection1 node=127.0.0.1:49831_un%2Fr C559_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:49831_un%2Fr, base_url=http://127.0.0.1:49831/un/r, leader=true}
[junit4:junit4] 2> 1370900 T2688 C559 P49831 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1370904 T2688 C559 P49831 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@698b7f01 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a0a6710),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1370906 T2688 C559 P49831 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1370906 T2688 C559 P49831 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@698b7f01 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a0a6710),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@698b7f01 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a0a6710),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1370907 T2688 C559 P49831 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1370907 T2688 C559 P49831 oass.SolrIndexSearcher.<init> Opening Searcher@5bbf74c3 main
[junit4:junit4] 2> 1370908 T2688 C559 P49831 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1370910 T2698 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5bbf74c3 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1370911 T2688 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 11
[junit4:junit4] 2> ASYNC NEW_CORE C560 name=collection1 org.apache.solr.core.SolrCore@6553bb66 url=http://127.0.0.1:49835/un/r/collection1 node=127.0.0.1:49835_un%2Fr C560_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49835_un%2Fr, base_url=http://127.0.0.1:49835/un/r, leader=true}
[junit4:junit4] 2> 1370932 T2705 C560 P49835 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:49835/un/r/collection1/, StdNode: http://127.0.0.1:49841/un/r/collection1/, StdNode: http://127.0.0.1:49838/un/r/collection1/, StdNode: http://127.0.0.1:49845/un/r/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> C557_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49845_un%2Fr, base_url=http://127.0.0.1:49845/un/r}
[junit4:junit4] 2> 1370958 T2757 C557 P49845 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1370960 T2706 C560 P49835 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1370962 T2723 C558 P49838 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1370963 T2723 C558 P49838 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18d55090 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8a5a8fe),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18d55090 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8a5a8fe),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1370964 T2723 C558 P49838 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1370964 T2757 C557 P49845 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@31abb139 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2ae290c6),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@31abb139 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2ae290c6),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1370965 T2757 C557 P49845 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> ASYNC NEW_CORE C561 name=collection1 org.apache.solr.core.SolrCore@6b3f6000 url=http://127.0.0.1:49841/un/r/collection1 node=127.0.0.1:49841_un%2Fr C561_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49841_un%2Fr, base_url=http://127.0.0.1:49841/un/r}
[junit4:junit4] 2> 1370964 T2740 C561 P49841 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1370964 T2723 C558 P49838 oass.SolrIndexSearcher.<init> Opening Searcher@3bf03b17 main
[junit4:junit4] 2> 1370967 T2723 C558 P49838 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1370969 T2732 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3bf03b17 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1370970 T2723 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r 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> 1370964 T2706 C560 P49835 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@25b0532 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f2aa497),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@25b0532 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f2aa497),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1370971 T2706 C560 P49835 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1370972 T2706 C560 P49835 oass.SolrIndexSearcher.<init> Opening Searcher@30ef67f2 main
[junit4:junit4] 2> 1370973 T2706 C560 P49835 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1370973 T2757 C557 P49845 oass.SolrIndexSearcher.<init> Opening Searcher@59a9829a main
[junit4:junit4] 2> 1370974 T2757 C557 P49845 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1370975 T2740 C561 P49841 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c0fbc41 lockFactory=org.apache.lucene.store.NativeFSLockFactory@37c2317f),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c0fbc41 lockFactory=org.apache.lucene.store.NativeFSLockFactory@37c2317f),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1370975 T2740 C561 P49841 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1370977 T2716 oasc.JmxMonitoredMap.put WARN Failed to register info bean: searcher javax.management.InstanceNotFoundException: solr/collection1:type=searcher,id=org.apache.solr.search.SolrIndexSearcher
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getMBean(DefaultMBeanServerInterceptor.java:1095)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.exclusiveUnregisterMBean(DefaultMBeanServerInterceptor.java:427)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.unregisterMBean(DefaultMBeanServerInterceptor.java:415)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.unregisterMBean(JmxMBeanServer.java:546)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:138)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4] 2> at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:299)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1846)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.access$000(SolrCore.java:135)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1723)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 1370977 T2767 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@59a9829a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1370978 T2716 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@30ef67f2 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1370980 T2740 C561 P49841 oass.SolrIndexSearcher.<init> Opening Searcher@386752cf main
[junit4:junit4] 2> 1370980 T2706 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 20
[junit4:junit4] 2> 1370982 T2748 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@386752cf main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1370983 T2740 C561 P49841 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1370983 T2740 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 20
[junit4:junit4] 2> 1370984 T2757 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 26
[junit4:junit4] 2> 1370985 T2705 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 54
[junit4:junit4] 2> 1370988 T2672 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1370993 T2707 C560 P49835 oasc.SolrCore.execute [collection1] webapp=/un/r path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1370999 T2741 C561 P49841 oasc.SolrCore.execute [collection1] webapp=/un/r path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1371003 T2725 C558 P49838 oasc.SolrCore.execute [collection1] webapp=/un/r path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1371008 T2758 C557 P49845 oasc.SolrCore.execute [collection1] webapp=/un/r path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1373016 T2686 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438731189838938112)} 0 2
[junit4:junit4] 2> 1373028 T2741 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={update.distrib=FROMLEADER&_version_=-1438731189845229568&update.from=http://127.0.0.1:49835/un/r/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438731189845229568)} 0 3
[junit4:junit4] 2> 1373034 T2758 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={update.distrib=FROMLEADER&_version_=-1438731189850472448&update.from=http://127.0.0.1:49838/un/r/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438731189850472448)} 0 2
[junit4:junit4] 2> 1373036 T2725 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438731189850472448)} 0 11
[junit4:junit4] 2> 1373038 T2707 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438731189845229568)} 0 18
[junit4:junit4] 2> 1373045 T2687 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[a!0 (1438731189869346816)]} 0 2
[junit4:junit4] 2> 1373060 T2759 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1438731189881929728)]} 0 1
[junit4:junit4] 2> 1373062 T2726 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49841/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!0 (1438731189881929728)]} 0 7
[junit4:junit4] 2> 1373063 T2742 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[a!0]} 0 14
[junit4:junit4] 2> 1373068 T2689 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[b!1 (1438731189894512640)]} 0 1
[junit4:junit4] 2> 1373086 T2737 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1438731189903949824)]} 0 1
[junit4:junit4] 2> 1373087 T2708 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!1 (1438731189903949824)]} 0 12
[junit4:junit4] 2> 1373088 T2721 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[b!1]} 0 16
[junit4:junit4] 2> 1373094 T2690 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[c!2 (1438731189921775616)]} 0 0
[junit4:junit4] 2> 1373106 T2739 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1438731189932261376)]} 0 0
[junit4:junit4] 2> 1373108 T2709 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49841/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!2 (1438731189932261376)]} 0 6
[junit4:junit4] 2> 1373110 T2738 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[c!2]} 0 13
[junit4:junit4] 2> 1373114 T2685 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[d!3 (1438731189942747136)]} 0 1
[junit4:junit4] 2> 1373124 T2754 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1438731189950087168)]} 0 1
[junit4:junit4] 2> 1373125 T2722 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!3 (1438731189950087168)]} 0 6
[junit4:junit4] 2> 1373126 T2710 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[d!3]} 0 9
[junit4:junit4] 2> 1373130 T2688 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[e!4 (1438731189960572928)]} 0 1
[junit4:junit4] 2> 1373143 T2755 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1438731189966864384)]} 0 4
[junit4:junit4] 2> 1373147 T2724 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!4 (1438731189966864384)]} 0 12
[junit4:junit4] 2> 1373148 T2706 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[e!4]} 0 15
[junit4:junit4] 2> 1373152 T2686 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[f!5 (1438731189982593024)]} 0 1
[junit4:junit4] 2> 1373163 T2757 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1438731189992030208)]} 0 1
[junit4:junit4] 2> 1373164 T2723 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1438731189992030208)]} 0 5
[junit4:junit4] 2> 1373165 T2756 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[f!5]} 0 10
[junit4:junit4] 2> 1373169 T2687 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[g!6 (1438731190000418816)]} 0 1
[junit4:junit4] 2> 1373180 T2741 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1438731190008807424)]} 0 1
[junit4:junit4] 2> 1373181 T2705 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49841/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!6 (1438731190008807424)]} 0 5
[junit4:junit4] 2> 1373182 T2740 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[g!6]} 0 9
[junit4:junit4] 2> 1373186 T2689 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[h!7 (1438731190019293184)]} 0 1
[junit4:junit4] 2> 1373193 T2742 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1438731190022438912)]} 0 1
[junit4:junit4] 2> 1373194 T2707 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[h!7 (1438731190022438912)]} 0 5
[junit4:junit4] 2> 1373198 T2690 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[i!8 (1438731190030827520)]} 0 1
[junit4:junit4] 2> 1373212 T2739 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1438731190043410432)]} 0 0
[junit4:junit4] 2> 1373214 T2708 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49841/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!8 (1438731190043410432)]} 0 6
[junit4:junit4] 2> 1373214 T2737 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[i!8]} 0 13
[junit4:junit4] 2> 1373223 T2685 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[j!9 (1438731190058090496)]} 0 1
[junit4:junit4] 2> 1373235 T2738 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1438731190066479104)]} 0 1
[junit4:junit4] 2> 1373236 T2709 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[j!9 (1438731190066479104)]} 0 5
[junit4:junit4] 2> 1373239 T2688 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[k!10 (1438731190074867712)]} 0 0
[junit4:junit4] 2> 1373247 T2741 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1438731190080110592)]} 0 0
[junit4:junit4] 2> 1373248 T2710 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!10 (1438731190080110592)]} 0 4
[junit4:junit4] 2> 1373249 T2725 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[k!10]} 0 7
[junit4:junit4] 2> 1373252 T2686 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[l!11 (1438731190088499200)]} 0 0
[junit4:junit4] 2> 1373261 T2758 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1438731190094790656)]} 0 0
[junit4:junit4] 2> 1373262 T2726 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!11 (1438731190094790656)]} 0 4
[junit4:junit4] 2> 1373263 T2706 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[l!11]} 0 8
[junit4:junit4] 2> 1373268 T2687 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[m!12 (1438731190103179264)]} 0 2
[junit4:junit4] 2> 1373294 T2759 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1438731190121005056)]} 0 1
[junit4:junit4] 2> 1373295 T2721 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[m!12 (1438731190121005056)]} 0 12
[junit4:junit4] 2> 1373298 T2689 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[n!13 (1438731190136733696)]} 0 0
[junit4:junit4] 2> 1373308 T2740 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1438731190144073728)]} 0 0
[junit4:junit4] 2> 1373310 T2705 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!13 (1438731190144073728)]} 0 5
[junit4:junit4] 2> 1373311 T2754 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[n!13]} 0 9
[junit4:junit4] 2> 1373315 T2690 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[o!14 (1438731190153510912)]} 0 1
[junit4:junit4] 2> 1373326 T2755 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1438731190161899520)]} 0 1
[junit4:junit4] 2> 1373327 T2722 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!14 (1438731190161899520)]} 0 5
[junit4:junit4] 2> 1373328 T2707 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[o!14]} 0 10
[junit4:junit4] 2> 1373333 T2685 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[p!15 (1438731190172385280)]} 0 1
[junit4:junit4] 2> 1373347 T2742 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1438731190184968192)]} 0 0
[junit4:junit4] 2> 1373349 T2708 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!15 (1438731190184968192)]} 0 6
[junit4:junit4] 2> 1373350 T2757 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[p!15]} 0 10
[junit4:junit4] 2> 1373354 T2688 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[q!16 (1438731190194405376)]} 0 1
[junit4:junit4] 2> 1373362 T2739 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1438731190199648256)]} 0 1
[junit4:junit4] 2> 1373363 T2709 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[q!16 (1438731190199648256)]} 0 5
[junit4:junit4] 2> 1373367 T2686 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[r!17 (1438731190209085440)]} 0 0
[junit4:junit4] 2> 1373378 T2758 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1438731190216425472)]} 0 1
[junit4:junit4] 2> 1373379 T2724 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!17 (1438731190216425472)]} 0 5
[junit4:junit4] 2> 1373381 T2756 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[r!17]} 0 10
[junit4:junit4] 2> 1373385 T2687 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[s!18 (1438731190226911232)]} 0 1
[junit4:junit4] 2> 1373395 T2737 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1438731190234251264)]} 0 1
[junit4:junit4] 2> 1373396 T2710 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!18 (1438731190234251264)]} 0 5
[junit4:junit4] 2> 1373398 T2723 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[s!18]} 0 10
[junit4:junit4] 2> 1373407 T2689 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[t!19 (1438731190247882752)]} 0 5
[junit4:junit4] 2> 1373417 T2738 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1438731190257319936)]} 0 1
[junit4:junit4] 2> 1373418 T2706 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[t!19 (1438731190257319936)]} 0 6
[junit4:junit4] 2> 1373424 T2690 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[u!20 (1438731190267805696)]} 0 1
[junit4:junit4] 2> 1373430 T2759 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1438731190272000000)]} 0 1
[junit4:junit4] 2> 1373431 T2725 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[u!20 (1438731190272000000)]} 0 4
[junit4:junit4] 2> 1373434 T2688 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[v!21 (1438731190278291456)]} 0 1
[junit4:junit4] 2> 1373442 T2740 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1438731190284582912)]} 0 1
[junit4:junit4] 2> 1373444 T2707 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!21 (1438731190284582912)]} 0 5
[junit4:junit4] 2> 1373445 T2755 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[v!21]} 0 9
[junit4:junit4] 2> 1373449 T2686 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[w!22 (1438731190295068672)]} 0 1
[junit4:junit4] 2> 1373459 T2739 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1438731190302408704)]} 0 1
[junit4:junit4] 2> 1373460 T2708 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49841/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!22 (1438731190302408704)]} 0 5
[junit4:junit4] 2> 1373461 T2742 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[w!22]} 0 8
[junit4:junit4] 2> 1373465 T2687 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[x!23 (1438731190311845888)]} 0 0
[junit4:junit4] 2> 1373481 T2758 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1438731190323380224)]} 0 1
[junit4:junit4] 2> 1373482 T2721 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!23 (1438731190323380224)]} 0 6
[junit4:junit4] 2> 1373483 T2757 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[x!23]} 0 10
[junit4:junit4] 2> 1373493 T2689 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[y!24 (1438731190340157440)]} 0 1
[junit4:junit4] 2> 1373506 T2756 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1438731190351691776)]} 0 0
[junit4:junit4] 2> 1373508 T2722 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[y!24 (1438731190351691776)]} 0 4
[junit4:junit4] 2> 1373511 T2685 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[z!25 (1438731190360080384)]} 0 0
[junit4:junit4] 2> 1373520 T2737 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1438731190366371840)]} 0 1
[junit4:junit4] 2> 1373521 T2709 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!25 (1438731190366371840)]} 0 4
[junit4:junit4] 2> 1373522 T2754 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[z!25]} 0 8
[junit4:junit4] 2> 1373526 T2690 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[a!26 (1438731190374760448)]} 0 1
[junit4:junit4] 2> 1373532 T2759 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1438731190378954752)]} 0 1
[junit4:junit4] 2> 1373533 T2724 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[a!26 (1438731190378954752)]} 0 4
[junit4:junit4] 2> 1373541 T2688 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[b!27 (1438731190387343360)]} 0 4
[junit4:junit4] 2> 1373557 T2741 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1438731190405169152)]} 0 1
[junit4:junit4] 2> 1373558 T2710 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[b!27 (1438731190405169152)]} 0 5
[junit4:junit4] 2> 1373565 T2686 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[c!28 (1438731190415654912)]} 0 1
[junit4:junit4] 2> 1373576 T2738 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1438731190424043520)]} 0 1
[junit4:junit4] 2> 1373577 T2705 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!28 (1438731190424043520)]} 0 5
[junit4:junit4] 2> 1373579 T2755 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[c!28]} 0 11
[junit4:junit4] 2> 1373593 T2687 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[d!29 (1438731190446063616)]} 0 1
[junit4:junit4] 2> 1373607 T2758 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1438731190453403648)]} 0 0
[junit4:junit4] 2> 1373612 T2723 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[d!29 (1438731190453403648)]} 0 11
[junit4:junit4] 2> 1373619 T2689 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[e!30 (1438731190473326592)]} 0 0
[junit4:junit4] 2> 1373630 T2756 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1438731190481715200)]} 0 1
[junit4:junit4] 2> 1373631 T2726 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!30 (1438731190481715200)]} 0 5
[junit4:junit4] 2> 1373632 T2757 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[e!30]} 0 9
[junit4:junit4] 2> 1373636 T2685 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[f!31 (1438731190491152384)]} 0 1
[junit4:junit4] 2> 1373646 T2754 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1438731190497443840)]} 0 1
[junit4:junit4] 2> 1373647 T2725 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1438731190497443840)]} 0 5
[junit4:junit4] 2> 1373648 T2706 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[f!31]} 0 9
[junit4:junit4] 2> 1373652 T2690 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[g!32 (1438731190507929600)]} 0 1
[junit4:junit4] 2> 1373661 T2739 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1438731190514221056)]} 0 0
[junit4:junit4] 2> 1373662 T2707 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49841/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!32 (1438731190514221056)]} 0 4
[junit4:junit4] 2> 1373663 T2740 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[g!32]} 0 8
[junit4:junit4] 2> 1373668 T2688 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[h!33 (1438731190523658240)]} 0 2
[junit4:junit4] 2> 1373681 T2742 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1438731190528901120)]} 0 1
[junit4:junit4] 2> 1373682 T2708 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[h!33 (1438731190528901120)]} 0 11
[junit4:junit4] 2> 1373686 T2686 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[i!34 (1438731190543581184)]} 0 0
[junit4:junit4] 2> 1373702 T2737 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1438731190549872640)]} 0 0
[junit4:junit4] 2> 1373704 T2709 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[i!34 (1438731190549872640)]} 0 12
[junit4:junit4] 2> 1373709 T2687 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[j!35 (1438731190566649856)]} 0 1
[junit4:junit4] 2> 1373718 T2741 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1438731190573989888)]} 0 0
[junit4:junit4] 2> 1373720 T2710 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[j!35 (1438731190573989888)]} 0 6
[junit4:junit4] 2> 1373723 T2689 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[k!36 (1438731190582378496)]} 0 0
[junit4:junit4] 2> 1373730 T2738 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1438731190586572800)]} 0 1
[junit4:junit4] 2> 1373731 T2705 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[k!36 (1438731190586572800)]} 0 4
[junit4:junit4] 2> 1373735 T2685 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[l!37 (1438731190593912832)]} 0 1
[junit4:junit4] 2> 1373745 T2755 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1438731190601252864)]} 0 1
[junit4:junit4] 2> 1373746 T2721 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1438731190601252864)]} 0 5
[junit4:junit4] 2> 1373747 T2759 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[l!37]} 0 9
[junit4:junit4] 2> 1373751 T2690 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[m!38 (1438731190610690048)]} 0 1
[junit4:junit4] 2> 1373764 T2758 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1438731190621175808)]} 0 1
[junit4:junit4] 2> 1373766 T2722 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!38 (1438731190621175808)]} 0 6
[junit4:junit4] 2> 1373768 T2706 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[m!38]} 0 11
[junit4:junit4] 2> 1373772 T2688 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[n!39 (1438731190632710144)]} 0 1
[junit4:junit4] 2> 1373781 T2739 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1438731190640050176)]} 0 0
[junit4:junit4] 2> 1373782 T2707 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!39 (1438731190640050176)]} 0 4
[junit4:junit4] 2> 1373783 T2756 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[n!39]} 0 8
[junit4:junit4] 2> 1373788 T2686 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[o!40 (1438731190649487360)]} 0 1
[junit4:junit4] 2> 1373797 T2754 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1438731190656827392)]} 0 0
[junit4:junit4] 2> 1373798 T2724 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!40 (1438731190656827392)]} 0 4
[junit4:junit4] 2> 1373799 T2757 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[o!40]} 0 8
[junit4:junit4] 2> 1373803 T2687 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[p!41 (1438731190666264576)]} 0 0
[junit4:junit4] 2> 1373818 T2742 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1438731190678847488)]} 0 1
[junit4:junit4] 2> 1373819 T2708 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49841/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!41 (1438731190678847488)]} 0 5
[junit4:junit4] 2> 1373820 T2740 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[p!41]} 0 9
[junit4:junit4] 2> 1373824 T2689 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[q!42 (1438731190687236096)]} 0 1
[junit4:junit4] 2> 1373834 T2741 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1438731190694576128)]} 0 1
[junit4:junit4] 2> 1373835 T2710 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!42 (1438731190694576128)]} 0 5
[junit4:junit4] 2> 1373836 T2755 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[q!42]} 0 9
[junit4:junit4] 2> 1373840 T2690 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[r!43 (1438731190705061888)]} 0 1
[junit4:junit4] 2> 1373850 T2758 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1438731190712401920)]} 0 1
[junit4:junit4] 2> 1373851 T2723 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!43 (1438731190712401920)]} 0 5
[junit4:junit4] 2> 1373853 T2705 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[r!43]} 0 10
[junit4:junit4] 2> 1373856 T2688 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[s!44 (1438731190721839104)]} 0 0
[junit4:junit4] 2> 1373866 T2739 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1438731190728130560)]} 0 1
[junit4:junit4] 2> 1373867 T2706 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49841/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!44 (1438731190728130560)]} 0 5
[junit4:junit4] 2> 1373868 T2738 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[s!44]} 0 9
[junit4:junit4] 2> 1373877 T2686 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[t!45 (1438731190740713472)]} 0 4
[junit4:junit4] 2> 1373895 T2737 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1438731190750150656)]} 0 1
[junit4:junit4] 2> 1373896 T2707 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!45 (1438731190750150656)]} 0 13
[junit4:junit4] 2> 1373897 T2756 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[t!45]} 0 17
[junit4:junit4] 2> 1373904 T2687 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[u!46 (1438731190771122176)]} 0 1
[junit4:junit4] 2> 1373914 T2754 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1438731190778462208)]} 0 1
[junit4:junit4] 2> 1373915 T2725 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49841/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!46 (1438731190778462208)]} 0 5
[junit4:junit4] 2> 1373916 T2742 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[u!46]} 0 9
[junit4:junit4] 2> 1373919 T2689 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[v!47 (1438731190787899392)]} 0 0
[junit4:junit4] 2> 1373928 T2740 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1438731190794190848)]} 0 0
[junit4:junit4] 2> 1373930 T2709 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49845/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!47 (1438731190794190848)]} 0 5
[junit4:junit4] 2> 1373931 T2757 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[v!47]} 0 9
[junit4:junit4] 2> 1373935 T2685 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[w!48 (1438731190803628032)]} 0 1
[junit4:junit4] 2> 1373944 T2739 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1438731190809919488)]} 0 1
[junit4:junit4] 2> 1373950 T2708 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49841/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!48 (1438731190809919488)]} 0 10
[junit4:junit4] 2> 1373952 T2741 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[w!48]} 0 14
[junit4:junit4] 2> 1373962 T2690 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[x!49 (1438731190831939584)]} 0 1
[junit4:junit4] 2> 1373969 T2755 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1438731190836133888)]} 0 0
[junit4:junit4] 2> 1373970 T2721 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[x!49 (1438731190836133888)]} 0 5
[junit4:junit4] 2> 1373974 T2688 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[y!50 (1438731190845571072)]} 0 0
[junit4:junit4] 2> 1373985 T2759 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1438731190852911104)]} 0 1
[junit4:junit4] 2> 1373986 T2722 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!50 (1438731190852911104)]} 0 6
[junit4:junit4] 2> 1373988 T2710 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[y!50]} 0 10
[junit4:junit4] 2> 1373991 T2686 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[z!51 (1438731190863396864)]} 0 0
[junit4:junit4] 2> 1373998 T2738 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1438731190867591168)]} 0 0
[junit4:junit4] 2> 1374001 T2705 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[z!51 (1438731190867591168)]} 0 6
[junit4:junit4] 2> 1374005 T2687 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[a!52 (1438731190877028352)]} 0 1
[junit4:junit4] 2> 1374023 T2758 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1438731190890659840)]} 0 0
[junit4:junit4] 2> 1374025 T2724 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!52 (1438731190890659840)]} 0 9
[junit4:junit4] 2> 1374026 T2706 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[a!52]} 0 14
[junit4:junit4] 2> 1374030 T2689 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[b!53 (1438731190903242752)]} 0 1
[junit4:junit4] 2> 1374040 T2737 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1438731190910582784)]} 0 1
[junit4:junit4] 2> 1374041 T2707 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!53 (1438731190910582784)]} 0 5
[junit4:junit4] 2> 1374042 T2726 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[b!53]} 0 9
[junit4:junit4] 2> 1374046 T2685 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[c!54 (1438731190921068544)]} 0 1
[junit4:junit4] 2> 1374057 T2742 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49835/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1438731190927360000)]} 0 1
[junit4:junit4] 2> 1374058 T2709 C560 P49835 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!54 (1438731190927360000)]} 0 6
[junit4:junit4] 2> 1374059 T2723 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[c!54]} 0 10
[junit4:junit4] 2> 1374063 T2690 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[d!55 (1438731190937845760)]} 0 1
[junit4:junit4] 2> 1374079 T2756 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1438731190947282944)]} 0 0
[junit4:junit4] 2> 1374081 T2725 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49841/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1438731190947282944)]} 0 11
[junit4:junit4] 2> 1374082 T2740 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[d!55]} 0 15
[junit4:junit4] 2> 1374089 T2688 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[e!56 (1438731190965108736)]} 0 1
[junit4:junit4] 2> 1374104 T2754 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1438731190970351616)]} 0 1
[junit4:junit4] 2> 1374106 T2721 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[e!56 (1438731190970351616)]} 0 13
[junit4:junit4] 2> 1374110 T2686 C559 P49831 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[f!57 (1438731190987128832)]} 0 1
[junit4:junit4] 2> 1374119 T2757 C557 P49845 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49838/un/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1438731190994468864)]} 0 0
[junit4:junit4] 2> 1374121 T2722 C558 P49838 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={distrib.from=http://127.0.0.1:49841/un/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!57 (1438731190994468864)]} 0 5
[junit4:junit4] 2> 1374122 T2739 C561 P49841 oasup.LogUpdateProcessor.finish [collection1] webapp=/un/r path=/update params={wt=javabin&version=2} {add=[f
[...truncated too long message...]
ng=202,adds=202,deletesById=98,deletesByQuery=0,errors=0,cumulative_adds=244,cumulative_deletesById=98,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 1413817 T2672 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 1413818 T2672 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 1413818 T2672 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> C588_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49845_un%2Fr, base_url=http://127.0.0.1:49845/un/r, leader=true}
[junit4:junit4] 2> 1413828 T2672 C588 P49845 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@31abb139 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2ae290c6),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@31abb139 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2ae290c6),segFN=segments_5,generation=5}
[junit4:junit4] 2> 1413829 T2672 C588 P49845 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 1413834 T2672 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1413834 T2672 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1413836 T2672 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4/index;done=false>>]
[junit4:junit4] 2> 1413839 T2672 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4/index
[junit4:junit4] 2> 1413845 T2672 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4;done=false>>]
[junit4:junit4] 2> 1413846 T2672 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372080948806/jetty4
[junit4:junit4] 2> 1413848 T2797 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89920697061605388-127.0.0.1:49845_un%2Fr-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 1413866 T2672 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/un/r,null}
[junit4:junit4] 2> 1413961 T2672 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1413968 T2672 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:49828 49828
[junit4:junit4] 2> 1414071 T2672 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 49831
[junit4:junit4] 2> !!!! WARNING: best effort to remove /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-1372080948806 FAILED !!!!!
[junit4:junit4] 2> 1414073 T2672 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1414074 T2672 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:49828 49828
[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=B19E8151CB3CD84D -Dtests.slow=true -Dtests.locale=sq_AL -Dtests.timezone=Antarctica/Casey -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR 76.3s | ShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:49835/un/r returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([B19E8151CB3CD84D:30780F49BC63B871]: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:724)
[junit4:junit4] 2> 1414103 T2672 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 76261 T2671 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> 1415153 T2763 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1415154 T2763 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 1415154 T2763 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=PostingsFormat(name=MockRandom), _version_=PostingsFormat(name=NestedPulsing), n_ti=Pulsing41(freqCutoff=6 minBlockSize=46 maxBlockSize=92)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {}, locale=sq_AL, timezone=Antarctica/Casey
[junit4:junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=2,threads=3,free=141948736,total=326565888
[junit4:junit4] 2> NOTE: All tests run in this JVM: [DirectUpdateHandlerOptimizeTest, LoggingHandlerTest, QueryEqualityTest, BadComponentTest, RegexBoostProcessorTest, TestNumberUtils, MinimalSchemaTest, TestCSVResponseWriter, OverseerCollectionProcessorTest, NotRequiredUniqueKeyTest, SpellCheckCollatorTest, CoreAdminHandlerTest, PingRequestHandlerTest, UpdateParamsTest, SimpleFacetsTest, FileBasedSpellCheckerTest, TestSurroundQueryParser, DateMathParserTest, TestWordDelimiterFilterFactory, TestPHPSerializedResponseWriter, SolrCoreCheckLockOnStartupTest, SynonymTokenizerTest, SoftAutoCommitTest, TestCloudManagedSchemaAddField, TestSearchPerf, TestDFRSimilarityFactory, TestSystemIdResolver, TestPhraseSuggestions, QueryElevationComponentTest, SortByFunctionTest, HighlighterTest, SuggesterWFSTTest, TestIBSimilarityFactory, TestPerFieldSimilarity, TestCodecSupport, LeaderElectionIntegrationTest, JSONWriterTest, TestRandomFaceting, SuggesterFSTTest, TestCoreContainer, UnloadDistributedZkTest, SolrIndexConfigTest, DisMaxRequestHandlerTest, TestReversedWildcardFilterFactory, TestFieldCollectionResource, TestArbitraryIndexDir, TestPropInjectDefaults, PrimitiveFieldTypeTest, SolrInfoMBeanTest, SolrRequestParserTest, SOLR749Test, AlternateDirectoryTest, ClusterStateUpdateTest, TestDynamicFieldResource, TestSolrDeletionPolicy2, TestMaxScoreQueryParser, SignatureUpdateProcessorFactoryTest, MoreLikeThisHandlerTest, TestStressReorder, TestFunctionQuery, TestSuggestSpellingConverter, TestFastWriter, TestAnalyzedSuggestions, BadIndexSchemaTest, XsltUpdateRequestHandlerTest, TestSolr4Spatial, TestTrie, PeerSyncTest, DebugComponentTest, URLClassifyProcessorTest, TestSolrQueryParser, DocValuesMultiTest, SuggesterTSTTest, StatsComponentTest, TestAtomicUpdateErrorCases, LukeRequestHandlerTest, ResourceLoaderTest, TestDocSet, TestSolrXmlPersistence, SpatialFilterTest, TestCopyFieldCollectionResource, TestRecovery, ExternalFileFieldSortTest, TestFuzzyAnalyzedSuggestions, DistanceFunctionTest, TestWriterPerf, OpenExchangeRatesOrgProviderTest, FullSolrCloudDistribCmdsTest, TestDocumentBuilder, TestFiltering, ZkNodePropsTest, TestSerializedLuceneMatchVersion, TestSchemaNameResource, TestManagedSchema, PathHierarchyTokenizerFactoryTest, UUIDFieldTest, TestIndexingPerformance, TestPostingsSolrHighlighter, ShardRoutingCustomTest, HighlighterConfigTest, SolrCmdDistributorTest, CSVRequestHandlerTest, StatelessScriptUpdateProcessorFactoryTest, TestFieldTypeCollectionResource, LegacyHTMLStripCharFilterTest, TestLuceneMatchVersion, TestComponentsName, WordBreakSolrSpellCheckerTest, TestRealTimeGet, ChaosMonkeyNothingIsSafeTest, TestReplicationHandler, BasicDistributedZkTest, BadCopyFieldTest, PolyFieldTest, ReturnFieldsTest, EchoParamsTest, ShardSplitTest]
[junit4:junit4] Completed in 77.62s, 1 test, 1 error <<< FAILURES!
[...truncated 554 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:386: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:366: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build.xml:181: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/common-build.xml:437: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:1243: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:887: There were test failures: 297 suites, 1253 tests, 1 error, 18 ignored (6 assumptions)
Total time: 101 minutes 56 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure