You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/06/04 21:04:49 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1681 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1681/
1 tests failed.
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:47919/lzph 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:47919/lzph returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([4EB7BC79B6B60B06:CF513261C1E96B3A]: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:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
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:679)
Build Log:
[...truncated 9002 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 799104 T2585 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /lzph/
[junit4:junit4] 2> 799109 T2585 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./solrtest-ShardSplitTest-1370371704399
[junit4:junit4] 2> 799110 T2585 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 799111 T2586 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 799212 T2585 oasc.ZkTestServer.run start zk server on port:23784
[junit4:junit4] 2> 799213 T2585 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 799217 T2592 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@21e66348 name:ZooKeeperConnection Watcher:127.0.0.1:23784 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 799218 T2585 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 799218 T2585 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 799239 T2585 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 799243 T2594 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3a4ccbe5 name:ZooKeeperConnection Watcher:127.0.0.1:23784/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 799244 T2585 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 799244 T2585 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 799257 T2585 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 799260 T2585 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 799263 T2585 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 799271 T2585 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 799272 T2585 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 799287 T2585 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 799287 T2585 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 799391 T2585 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 799392 T2585 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 799395 T2585 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 799396 T2585 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 799407 T2585 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 799407 T2585 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 799410 T2585 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 799411 T2585 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 799415 T2585 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 799415 T2585 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 799418 T2585 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 799419 T2585 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 799422 T2585 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 799423 T2585 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 799685 T2585 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 799690 T2585 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:20484
[junit4:junit4] 2> 799690 T2585 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 799691 T2585 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 799691 T2585 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370371704723
[junit4:junit4] 2> 799692 T2585 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370371704723/solr.xml
[junit4:junit4] 2> 799692 T2585 oasc.CoreContainer.<init> New CoreContainer 2111492301
[junit4:junit4] 2> 799693 T2585 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370371704723/'
[junit4:junit4] 2> 799693 T2585 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370371704723/'
[junit4:junit4] 2> 799802 T2585 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 799803 T2585 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 799804 T2585 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 799804 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 799805 T2585 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 799805 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 799805 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 799806 T2585 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 799806 T2585 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 799807 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 799824 T2585 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 799824 T2585 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:23784/solr
[junit4:junit4] 2> 799825 T2585 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 799826 T2585 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 799828 T2605 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7a3900df name:ZooKeeperConnection Watcher:127.0.0.1:23784 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 799829 T2585 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 799831 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 799842 T2585 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 799844 T2607 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4c7ad4c name:ZooKeeperConnection Watcher:127.0.0.1:23784/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 799844 T2585 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 799846 T2585 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 799857 T2585 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 799860 T2585 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 799868 T2585 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:20484_lzph
[junit4:junit4] 2> 799869 T2585 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:20484_lzph
[junit4:junit4] 2> 799873 T2585 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 799889 T2585 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 799892 T2585 oasc.Overseer.start Overseer (id=89808680019951619-127.0.0.1:20484_lzph-n_0000000000) starting
[junit4:junit4] 2> 799906 T2585 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 799917 T2609 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 799918 T2585 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 799921 T2585 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 799923 T2585 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 799925 T2608 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 799929 T2610 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370371704723/collection1
[junit4:junit4] 2> 799929 T2610 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 799930 T2610 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 799930 T2610 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 799932 T2610 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370371704723/collection1/'
[junit4:junit4] 2> 799933 T2610 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1370371704723/collection1/lib/README' to classloader
[junit4:junit4] 2> 799934 T2610 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1370371704723/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 799983 T2610 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 800045 T2610 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 800146 T2610 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 800152 T2610 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 800708 T2610 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 800712 T2610 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 800715 T2610 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 800720 T2610 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 800743 T2610 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 800743 T2610 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1370371704723/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370371704398/control/data/
[junit4:junit4] 2> 800744 T2610 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@47503458
[junit4:junit4] 2> 800744 T2610 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 800745 T2610 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370371704398/control/data
[junit4:junit4] 2> 800745 T2610 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370371704398/control/data/index/
[junit4:junit4] 2> 800745 T2610 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370371704398/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 800746 T2610 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370371704398/control/data/index
[junit4:junit4] 2> 800750 T2610 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a762e09 lockFactory=org.apache.lucene.store.NativeFSLockFactory@21e48346),segFN=segments_1,generation=1}
[junit4:junit4] 2> 800751 T2610 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 800753 T2610 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 800754 T2610 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 800754 T2610 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 800755 T2610 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 800755 T2610 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 800755 T2610 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 800756 T2610 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 800756 T2610 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 800757 T2610 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 800766 T2610 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 800773 T2610 oass.SolrIndexSearcher.<init> Opening Searcher@55179e3f main
[junit4:junit4] 2> 800774 T2610 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370371704398/control/data/tlog
[junit4:junit4] 2> 800775 T2610 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 800775 T2610 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 800778 T2611 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@55179e3f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 800780 T2610 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 800780 T2610 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 801428 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 801429 T2608 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:20484_lzph",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:20484/lzph"}
[junit4:junit4] 2> 801429 T2608 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 801430 T2608 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 801444 T2607 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> 801783 T2610 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 801783 T2610 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:20484/lzph collection:control_collection shard:shard1
[junit4:junit4] 2> 801784 T2610 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 801801 T2610 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 801804 T2610 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 801804 T2610 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 801805 T2610 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:20484/lzph/collection1/
[junit4:junit4] 2> 801805 T2610 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 801805 T2610 oasc.SyncStrategy.syncToMe http://127.0.0.1:20484/lzph/collection1/ has no replicas
[junit4:junit4] 2> 801805 T2610 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:20484/lzph/collection1/
[junit4:junit4] 2> 801806 T2610 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 802948 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 802973 T2607 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> 803036 T2610 oasc.ZkController.register We are http://127.0.0.1:20484/lzph/collection1/ and leader is http://127.0.0.1:20484/lzph/collection1/
[junit4:junit4] 2> 803036 T2610 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:20484/lzph
[junit4:junit4] 2> 803036 T2610 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 803036 T2610 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 803037 T2610 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 803042 T2610 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 803043 T2585 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 803044 T2585 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 803044 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 803059 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 803060 T2585 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 803062 T2614 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6f789330 name:ZooKeeperConnection Watcher:127.0.0.1:23784/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 803063 T2585 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 803064 T2585 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 803066 T2585 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 803318 T2585 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 803321 T2585 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:47919
[junit4:junit4] 2> 803322 T2585 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 803323 T2585 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 803323 T2585 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370371708356
[junit4:junit4] 2> 803323 T2585 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370371708356/solr.xml
[junit4:junit4] 2> 803324 T2585 oasc.CoreContainer.<init> New CoreContainer 1622805060
[junit4:junit4] 2> 803325 T2585 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370371708356/'
[junit4:junit4] 2> 803325 T2585 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370371708356/'
[junit4:junit4] 2> 803438 T2585 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 803439 T2585 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 803439 T2585 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 803440 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 803440 T2585 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 803441 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 803441 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 803441 T2585 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 803442 T2585 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 803442 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 803457 T2585 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 803458 T2585 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:23784/solr
[junit4:junit4] 2> 803459 T2585 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 803460 T2585 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 803463 T2625 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@827cb6e name:ZooKeeperConnection Watcher:127.0.0.1:23784 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 803463 T2585 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 803478 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 803488 T2585 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 803490 T2627 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3b7ab07 name:ZooKeeperConnection Watcher:127.0.0.1:23784/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 803490 T2585 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 803500 T2585 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 804490 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 804491 T2608 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:20484_lzph",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:20484/lzph"}
[junit4:junit4] 2> 804504 T2627 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> 804504 T2585 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47919_lzph
[junit4:junit4] 2> 804504 T2607 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> 804504 T2614 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> 804506 T2585 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47919_lzph
[junit4:junit4] 2> 804518 T2627 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> 804518 T2614 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> 804518 T2607 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 804518 T2607 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> 804519 T2627 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 804519 T2614 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 804526 T2628 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370371708356/collection1
[junit4:junit4] 2> 804526 T2628 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 804527 T2628 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 804527 T2628 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 804528 T2628 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370371708356/collection1/'
[junit4:junit4] 2> 804530 T2628 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1370371708356/collection1/lib/README' to classloader
[junit4:junit4] 2> 804530 T2628 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1370371708356/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 804580 T2628 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 804637 T2628 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 804738 T2628 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 804743 T2628 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 805302 T2628 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 805306 T2628 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 805309 T2628 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 805314 T2628 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 805337 T2628 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 805337 T2628 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1370371708356/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty1/
[junit4:junit4] 2> 805337 T2628 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@47503458
[junit4:junit4] 2> 805338 T2628 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 805339 T2628 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty1
[junit4:junit4] 2> 805339 T2628 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty1/index/
[junit4:junit4] 2> 805339 T2628 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 805340 T2628 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty1/index
[junit4:junit4] 2> 805343 T2628 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@239ddbcc lockFactory=org.apache.lucene.store.NativeFSLockFactory@7a39e08d),segFN=segments_1,generation=1}
[junit4:junit4] 2> 805344 T2628 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 805346 T2628 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 805347 T2628 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 805347 T2628 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 805348 T2628 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 805349 T2628 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 805349 T2628 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 805349 T2628 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 805350 T2628 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 805350 T2628 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 805360 T2628 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 805367 T2628 oass.SolrIndexSearcher.<init> Opening Searcher@4f60956f main
[junit4:junit4] 2> 805367 T2628 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty1/tlog
[junit4:junit4] 2> 805368 T2628 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 805368 T2628 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 805373 T2629 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4f60956f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 805375 T2628 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 805375 T2628 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 806010 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 806011 T2608 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:47919_lzph",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47919/lzph"}
[junit4:junit4] 2> 806011 T2608 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 806011 T2608 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 806026 T2627 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> 806026 T2607 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> 806026 T2614 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> 806378 T2628 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 806378 T2628 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47919/lzph collection:collection1 shard:shard1
[junit4:junit4] 2> 806379 T2628 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 806397 T2628 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 806399 T2628 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 806400 T2628 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 806400 T2628 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:47919/lzph/collection1/
[junit4:junit4] 2> 806400 T2628 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 806400 T2628 oasc.SyncStrategy.syncToMe http://127.0.0.1:47919/lzph/collection1/ has no replicas
[junit4:junit4] 2> 806401 T2628 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:47919/lzph/collection1/
[junit4:junit4] 2> 806401 T2628 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 807530 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 807576 T2614 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> 807576 T2627 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> 807576 T2607 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> 807631 T2628 oasc.ZkController.register We are http://127.0.0.1:47919/lzph/collection1/ and leader is http://127.0.0.1:47919/lzph/collection1/
[junit4:junit4] 2> 807631 T2628 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47919/lzph
[junit4:junit4] 2> 807631 T2628 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 807631 T2628 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 807632 T2628 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 807633 T2628 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 807634 T2585 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 807635 T2585 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 807636 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 807907 T2585 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 807910 T2585 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:57623
[junit4:junit4] 2> 807910 T2585 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 807911 T2585 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 807911 T2585 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370371712940
[junit4:junit4] 2> 807912 T2585 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370371712940/solr.xml
[junit4:junit4] 2> 807912 T2585 oasc.CoreContainer.<init> New CoreContainer 593701924
[junit4:junit4] 2> 807913 T2585 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370371712940/'
[junit4:junit4] 2> 807913 T2585 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370371712940/'
[junit4:junit4] 2> 808024 T2585 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 808025 T2585 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 808025 T2585 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 808025 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 808026 T2585 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 808026 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 808027 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 808027 T2585 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 808028 T2585 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 808028 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 808044 T2585 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 808044 T2585 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:23784/solr
[junit4:junit4] 2> 808045 T2585 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 808046 T2585 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 808049 T2641 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@731c5581 name:ZooKeeperConnection Watcher:127.0.0.1:23784 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 808049 T2585 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 808064 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 808076 T2585 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 808077 T2643 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@21c1cb81 name:ZooKeeperConnection Watcher:127.0.0.1:23784/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 808078 T2585 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 808090 T2585 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 809089 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 809090 T2608 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:47919_lzph",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47919/lzph"}
[junit4:junit4] 2> 809093 T2585 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57623_lzph
[junit4:junit4] 2> 809106 T2614 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> 809106 T2627 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> 809106 T2607 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> 809106 T2643 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> 809106 T2585 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57623_lzph
[junit4:junit4] 2> 809110 T2627 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> 809110 T2643 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> 809110 T2614 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> 809111 T2607 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 809111 T2607 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> 809112 T2627 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 809112 T2643 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 809112 T2614 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 809125 T2644 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370371712940/collection1
[junit4:junit4] 2> 809125 T2644 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 809126 T2644 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 809126 T2644 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 809128 T2644 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370371712940/collection1/'
[junit4:junit4] 2> 809129 T2644 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1370371712940/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 809130 T2644 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1370371712940/collection1/lib/README' to classloader
[junit4:junit4] 2> 809179 T2644 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 809236 T2644 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 809338 T2644 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 809343 T2644 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 809902 T2644 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 809906 T2644 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 809908 T2644 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 809913 T2644 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 809936 T2644 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 809936 T2644 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1370371712940/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty2/
[junit4:junit4] 2> 809937 T2644 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@47503458
[junit4:junit4] 2> 809937 T2644 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 809938 T2644 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty2
[junit4:junit4] 2> 809938 T2644 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty2/index/
[junit4:junit4] 2> 809938 T2644 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 809939 T2644 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty2/index
[junit4:junit4] 2> 809942 T2644 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ffa7477 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ac76779),segFN=segments_1,generation=1}
[junit4:junit4] 2> 809942 T2644 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 809945 T2644 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 809945 T2644 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 809946 T2644 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 809946 T2644 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 809947 T2644 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 809947 T2644 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 809948 T2644 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 809948 T2644 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 809949 T2644 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 809957 T2644 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 809964 T2644 oass.SolrIndexSearcher.<init> Opening Searcher@5c96f83d main
[junit4:junit4] 2> 809964 T2644 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty2/tlog
[junit4:junit4] 2> 809965 T2644 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 809965 T2644 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 809970 T2645 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5c96f83d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 809972 T2644 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 809972 T2644 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 810611 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 810612 T2608 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:57623_lzph",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57623/lzph"}
[junit4:junit4] 2> 810612 T2608 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 810613 T2608 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 810626 T2627 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> 810627 T2607 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> 810626 T2643 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> 810626 T2614 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> 810975 T2644 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 810975 T2644 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57623/lzph collection:collection1 shard:shard2
[junit4:junit4] 2> 810976 T2644 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 810993 T2644 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 810996 T2644 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 810996 T2644 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 810996 T2644 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:57623/lzph/collection1/
[junit4:junit4] 2> 810997 T2644 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 810997 T2644 oasc.SyncStrategy.syncToMe http://127.0.0.1:57623/lzph/collection1/ has no replicas
[junit4:junit4] 2> 810997 T2644 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:57623/lzph/collection1/
[junit4:junit4] 2> 810997 T2644 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 812131 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 812156 T2627 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> 812156 T2614 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> 812156 T2643 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> 812156 T2607 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> 812176 T2644 oasc.ZkController.register We are http://127.0.0.1:57623/lzph/collection1/ and leader is http://127.0.0.1:57623/lzph/collection1/
[junit4:junit4] 2> 812176 T2644 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57623/lzph
[junit4:junit4] 2> 812176 T2644 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 812176 T2644 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 812177 T2644 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 812178 T2644 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 812179 T2585 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 812180 T2585 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 812181 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 812446 T2585 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 812449 T2585 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:16947
[junit4:junit4] 2> 812450 T2585 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 812450 T2585 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 812451 T2585 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370371717484
[junit4:junit4] 2> 812451 T2585 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370371717484/solr.xml
[junit4:junit4] 2> 812452 T2585 oasc.CoreContainer.<init> New CoreContainer 312720961
[junit4:junit4] 2> 812452 T2585 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370371717484/'
[junit4:junit4] 2> 812453 T2585 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370371717484/'
[junit4:junit4] 2> 812566 T2585 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 812567 T2585 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 812567 T2585 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 812568 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 812568 T2585 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 812569 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 812569 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 812570 T2585 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 812570 T2585 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 812571 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 812585 T2585 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 812586 T2585 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:23784/solr
[junit4:junit4] 2> 812586 T2585 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 812587 T2585 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 812592 T2657 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@293ea7ac name:ZooKeeperConnection Watcher:127.0.0.1:23784 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 812592 T2585 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 812607 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 812617 T2585 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 812619 T2659 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5876ead8 name:ZooKeeperConnection Watcher:127.0.0.1:23784/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 812620 T2585 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 812629 T2585 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 813633 T2585 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:16947_lzph
[junit4:junit4] 2> 813635 T2585 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:16947_lzph
[junit4:junit4] 2> 813638 T2627 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> 813638 T2614 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> 813638 T2659 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 813638 T2643 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> 813639 T2607 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 813639 T2607 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> 813640 T2627 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 813641 T2614 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 813641 T2643 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 813646 T2660 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370371717484/collection1
[junit4:junit4] 2> 813646 T2660 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 813647 T2660 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 813647 T2660 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 813648 T2660 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370371717484/collection1/'
[junit4:junit4] 2> 813650 T2660 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1370371717484/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 813650 T2660 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1370371717484/collection1/lib/README' to classloader
[junit4:junit4] 2> 813669 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 813670 T2608 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:57623_lzph",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57623/lzph"}
[junit4:junit4] 2> 813684 T2659 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> 813684 T2643 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> 813684 T2607 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> 813684 T2614 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> 813684 T2627 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> 813701 T2660 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 813759 T2660 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 813861 T2660 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 813866 T2660 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 814426 T2660 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 814431 T2660 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 814433 T2660 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 814438 T2660 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 814461 T2660 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 814462 T2660 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1370371717484/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3/
[junit4:junit4] 2> 814462 T2660 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@47503458
[junit4:junit4] 2> 814463 T2660 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 814463 T2660 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3
[junit4:junit4] 2> 814464 T2660 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3/index/
[junit4:junit4] 2> 814464 T2660 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 814465 T2660 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3/index
[junit4:junit4] 2> 814468 T2660 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@71eae893 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b8a8eb7),segFN=segments_1,generation=1}
[junit4:junit4] 2> 814469 T2660 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 814471 T2660 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 814472 T2660 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 814472 T2660 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 814473 T2660 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 814474 T2660 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 814474 T2660 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 814474 T2660 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 814475 T2660 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 814475 T2660 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 814485 T2660 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 814492 T2660 oass.SolrIndexSearcher.<init> Opening Searcher@273b4525 main
[junit4:junit4] 2> 814492 T2660 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3/tlog
[junit4:junit4] 2> 814493 T2660 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 814493 T2660 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 814498 T2661 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@273b4525 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 814500 T2660 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 814500 T2660 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 815188 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 815189 T2608 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:16947_lzph",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:16947/lzph"}
[junit4:junit4] 2> 815189 T2608 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 815190 T2608 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 815204 T2659 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> 815204 T2607 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> 815204 T2614 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> 815204 T2643 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> 815204 T2627 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> 815503 T2660 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 815503 T2660 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:16947/lzph collection:collection1 shard:shard1
[junit4:junit4] 2> 815506 T2660 oasc.ZkController.register We are http://127.0.0.1:16947/lzph/collection1/ and leader is http://127.0.0.1:47919/lzph/collection1/
[junit4:junit4] 2> 815506 T2660 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:16947/lzph
[junit4:junit4] 2> 815506 T2660 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 815507 T2660 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C724 name=collection1 org.apache.solr.core.SolrCore@77161026 url=http://127.0.0.1:16947/lzph/collection1 node=127.0.0.1:16947_lzph C724_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:16947_lzph, base_url=http://127.0.0.1:16947/lzph}
[junit4:junit4] 2> 815507 T2662 C724 P16947 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 815508 T2662 C724 P16947 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 815508 T2660 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 815508 T2662 C724 P16947 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 815509 T2662 C724 P16947 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 815509 T2585 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 815510 T2585 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 815510 T2662 C724 P16947 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 815510 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 815529 T2617 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 815779 T2585 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 815782 T2585 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:44787
[junit4:junit4] 2> 815783 T2585 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 815783 T2585 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 815783 T2585 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370371720817
[junit4:junit4] 2> 815784 T2585 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370371720817/solr.xml
[junit4:junit4] 2> 815784 T2585 oasc.CoreContainer.<init> New CoreContainer 751602041
[junit4:junit4] 2> 815785 T2585 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370371720817/'
[junit4:junit4] 2> 815785 T2585 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370371720817/'
[junit4:junit4] 2> 815894 T2585 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 815895 T2585 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 815896 T2585 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 815896 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 815896 T2585 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 815897 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 815897 T2585 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 815898 T2585 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 815898 T2585 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 815899 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 815915 T2585 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 815916 T2585 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:23784/solr
[junit4:junit4] 2> 815916 T2585 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 815917 T2585 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 815920 T2674 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4bd60af name:ZooKeeperConnection Watcher:127.0.0.1:23784 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 815921 T2585 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 815941 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 815953 T2585 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 815955 T2676 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15a5ad08 name:ZooKeeperConnection Watcher:127.0.0.1:23784/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 815955 T2585 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 815965 T2585 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 816708 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 816709 T2608 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:16947_lzph",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:16947/lzph"}
[junit4:junit4] 2> 816723 T2659 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> 816723 T2607 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> 816723 T2676 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> 816723 T2643 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> 816723 T2627 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> 816723 T2614 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> 816968 T2585 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44787_lzph
[junit4:junit4] 2> 816970 T2585 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:44787_lzph
[junit4:junit4] 2> 816973 T2659 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> 816973 T2614 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> 816973 T2627 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> 816973 T2643 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> 816974 T2607 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 816974 T2676 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 816974 T2607 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> 816975 T2676 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> 816975 T2659 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 816975 T2614 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 816994 T2627 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 816995 T2643 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 817000 T2677 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370371720817/collection1
[junit4:junit4] 2> 817000 T2677 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 817001 T2677 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 817001 T2677 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 817002 T2677 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370371720817/collection1/'
[junit4:junit4] 2> 817004 T2677 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1370371720817/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 817004 T2677 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1370371720817/collection1/lib/README' to classloader
[junit4:junit4] 2> 817059 T2677 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 817117 T2677 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 817219 T2677 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 817225 T2677 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 817531 T2617 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 817531 T2617 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:16947_lzph&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2002
[junit4:junit4] 2> 817786 T2677 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 817790 T2677 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 817793 T2677 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 817798 T2677 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 817821 T2677 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 817821 T2677 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1370371720817/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty4/
[junit4:junit4] 2> 817821 T2677 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@47503458
[junit4:junit4] 2> 817822 T2677 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 817823 T2677 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty4
[junit4:junit4] 2> 817823 T2677 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty4/index/
[junit4:junit4] 2> 817823 T2677 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 817824 T2677 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty4/index
[junit4:junit4] 2> 817827 T2677 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5b351311 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ede44c1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 817828 T2677 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 817830 T2677 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 817831 T2677 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 817831 T2677 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 817832 T2677 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 817833 T2677 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 817833 T2677 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 817833 T2677 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 817834 T2677 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 817834 T2677 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 817844 T2677 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 817851 T2677 oass.SolrIndexSearcher.<init> Opening Searcher@4dcd53fb main
[junit4:junit4] 2> 817851 T2677 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty4/tlog
[junit4:junit4] 2> 817852 T2677 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 817852 T2677 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 817857 T2678 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4dcd53fb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 817859 T2677 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 817859 T2677 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 818228 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 818229 T2608 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44787_lzph",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44787/lzph"}
[junit4:junit4] 2> 818230 T2608 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 818230 T2608 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 818243 T2614 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> 818243 T2659 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> 818243 T2627 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> 818243 T2607 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> 818243 T2643 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> 818243 T2676 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> 818863 T2677 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 818863 T2677 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:44787/lzph collection:collection1 shard:shard2
[junit4:junit4] 2> 818892 T2677 oasc.ZkController.register We are http://127.0.0.1:44787/lzph/collection1/ and leader is http://127.0.0.1:57623/lzph/collection1/
[junit4:junit4] 2> 818892 T2677 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44787/lzph
[junit4:junit4] 2> 818893 T2677 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 818893 T2677 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C725 name=collection1 org.apache.solr.core.SolrCore@4dc5c15b url=http://127.0.0.1:44787/lzph/collection1 node=127.0.0.1:44787_lzph C725_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:44787_lzph, base_url=http://127.0.0.1:44787/lzph}
[junit4:junit4] 2> 818893 T2679 C725 P44787 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 818894 T2679 C725 P44787 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 818894 T2677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 818894 T2679 C725 P44787 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 818895 T2679 C725 P44787 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 818895 T2585 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 818896 T2585 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 818896 T2679 C725 P44787 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 818897 T2585 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 818914 T2585 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 818914 T2633 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 818915 T2585 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 818915 T2585 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 818916 T2585 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C726 name=collection1 org.apache.solr.core.SolrCore@77161026 url=http://127.0.0.1:16947/lzph/collection1 node=127.0.0.1:16947_lzph C726_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:16947_lzph, base_url=http://127.0.0.1:16947/lzph}
[junit4:junit4] 2> 819533 T2662 C726 P16947 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:47919/lzph/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 819533 T2662 C726 P16947 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:16947/lzph START replicas=[http://127.0.0.1:47919/lzph/collection1/] nUpdates=100
[junit4:junit4] 2> 819533 T2662 C726 P16947 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 819534 T2662 C726 P16947 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 819534 T2662 C726 P16947 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 819534 T2662 C726 P16947 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 819535 T2662 C726 P16947 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 819535 T2662 C726 P16947 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:47919/lzph/collection1/. core=collection1
[junit4:junit4] 2> 819535 T2662 C726 P16947 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C727 name=collection1 org.apache.solr.core.SolrCore@49f4b117 url=http://127.0.0.1:47919/lzph/collection1 node=127.0.0.1:47919_lzph C727_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:47919_lzph, base_url=http://127.0.0.1:47919/lzph, leader=true}
[junit4:junit4] 2> 819542 T2618 C727 P47919 oasc.SolrCore.execute [collection1] webapp=/lzph path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 819545 T2619 C727 P47919 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 819548 T2619 C727 P47919 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@239ddbcc lockFactory=org.apache.lucene.store.NativeFSLockFactory@7a39e08d),segFN=segments_1,generation=1}
[junit4:junit4] 2> 819548 T2619 C727 P47919 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 819549 T2619 C727 P47919 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@239ddbcc lockFactory=org.apache.lucene.store.NativeFSLockFactory@7a39e08d),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@239ddbcc lockFactory=org.apache.lucene.store.NativeFSLockFactory@7a39e08d),segFN=segments_2,generation=2}
[junit4:junit4] 2> 819549 T2619 C727 P47919 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 819550 T2619 C727 P47919 oass.SolrIndexSearcher.<init> Opening Searcher@1adf48e2 realtime
[junit4:junit4] 2> 819550 T2619 C727 P47919 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 819550 T2619 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 819551 T2662 C726 P16947 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 819551 T2662 C726 P16947 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 819553 T2620 C727 P47919 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 819553 T2620 C727 P47919 oasc.SolrCore.execute [collection1] webapp=/lzph path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 819554 T2662 C726 P16947 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 819554 T2662 C726 P16947 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 819554 T2662 C726 P16947 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 819556 T2620 C727 P47919 oasc.SolrCore.execute [collection1] webapp=/lzph path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 819557 T2662 C726 P16947 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 819558 T2662 C726 P16947 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3/index.20130604144844846
[junit4:junit4] 2> 819559 T2662 C726 P16947 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@15aface7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3398a3ee) fullCopy=false
[junit4:junit4] 2> 819561 T2620 C727 P47919 oasc.SolrCore.execute [collection1] webapp=/lzph path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 819562 T2662 C726 P16947 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 819563 T2662 C726 P16947 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 819563 T2662 C726 P16947 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 819565 T2662 C726 P16947 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@71eae893 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b8a8eb7),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@71eae893 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b8a8eb7),segFN=segments_2,generation=2}
[junit4:junit4] 2> 819565 T2662 C726 P16947 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 819566 T2662 C726 P16947 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 819566 T2662 C726 P16947 oass.SolrIndexSearcher.<init> Opening Searcher@3f1fdf39 main
[junit4:junit4] 2> 819567 T2661 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3f1fdf39 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 819568 T2662 C726 P16947 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3/index.20130604144844846 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3/index.20130604144844846;done=true>>]
[junit4:junit4] 2> 819568 T2662 C726 P16947 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3/index.20130604144844846
[junit4:junit4] 2> 819568 T2662 C726 P16947 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3/index.20130604144844846
[junit4:junit4] 2> 819568 T2662 C726 P16947 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 819569 T2662 C726 P16947 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 819569 T2662 C726 P16947 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 819569 T2662 C726 P16947 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 819596 T2662 C726 P16947 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 819748 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 819749 T2608 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44787_lzph",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44787/lzph"}
[junit4:junit4] 2> 819753 T2608 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:16947_lzph",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:16947/lzph"}
[junit4:junit4] 2> 819767 T2614 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> 819767 T2627 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> 819767 T2676 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> 819767 T2643 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> 819767 T2607 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> 819767 T2659 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> 819916 T2633 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 819916 T2633 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:44787_lzph&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 819918 T2585 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 820920 T2585 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C725_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:44787_lzph, base_url=http://127.0.0.1:44787/lzph}
[junit4:junit4] 2> 821918 T2679 C725 P44787 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:57623/lzph/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 821918 T2679 C725 P44787 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:44787/lzph START replicas=[http://127.0.0.1:57623/lzph/collection1/] nUpdates=100
[junit4:junit4] 2> 821919 T2679 C725 P44787 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 821919 T2679 C725 P44787 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 821919 T2679 C725 P44787 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 821919 T2679 C725 P44787 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 821919 T2679 C725 P44787 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 821920 T2679 C725 P44787 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:57623/lzph/collection1/. core=collection1
[junit4:junit4] 2> 821920 T2679 C725 P44787 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 821922 T2585 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C728 name=collection1 org.apache.solr.core.SolrCore@15c1a1f3 url=http://127.0.0.1:57623/lzph/collection1 node=127.0.0.1:57623_lzph C728_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57623_lzph, base_url=http://127.0.0.1:57623/lzph, leader=true}
[junit4:junit4] 2> 821927 T2634 C728 P57623 oasc.SolrCore.execute [collection1] webapp=/lzph path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 821930 T2635 C728 P57623 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 821933 T2635 C728 P57623 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ffa7477 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ac76779),segFN=segments_1,generation=1}
[junit4:junit4] 2> 821933 T2635 C728 P57623 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 821934 T2635 C728 P57623 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ffa7477 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ac76779),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ffa7477 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ac76779),segFN=segments_2,generation=2}
[junit4:junit4] 2> 821934 T2635 C728 P57623 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 821935 T2635 C728 P57623 oass.SolrIndexSearcher.<init> Opening Searcher@6af2a92c realtime
[junit4:junit4] 2> 821935 T2635 C728 P57623 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 821935 T2635 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 821936 T2679 C725 P44787 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 821937 T2679 C725 P44787 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 821938 T2636 C728 P57623 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 821938 T2636 C728 P57623 oasc.SolrCore.execute [collection1] webapp=/lzph path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 821939 T2679 C725 P44787 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 821939 T2679 C725 P44787 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 821939 T2679 C725 P44787 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 821941 T2636 C728 P57623 oasc.SolrCore.execute [collection1] webapp=/lzph path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 821942 T2679 C725 P44787 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 821943 T2679 C725 P44787 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty4/index.20130604144847231
[junit4:junit4] 2> 821943 T2679 C725 P44787 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1016718e lockFactory=org.apache.lucene.store.NativeFSLockFactory@2ffb9458) fullCopy=false
[junit4:junit4] 2> 821945 T2636 C728 P57623 oasc.SolrCore.execute [collection1] webapp=/lzph path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 821946 T2679 C725 P44787 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 821947 T2679 C725 P44787 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 821947 T2679 C725 P44787 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 821949 T2679 C725 P44787 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5b351311 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ede44c1),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5b351311 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ede44c1),segFN=segments_2,generation=2}
[junit4:junit4] 2> 821949 T2679 C725 P44787 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 821949 T2679 C725 P44787 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 821950 T2679 C725 P44787 oass.SolrIndexSearcher.<init> Opening Searcher@c3a4ccb main
[junit4:junit4] 2> 821951 T2678 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c3a4ccb main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 821951 T2679 C725 P44787 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty4/index.20130604144847231 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty4/index.20130604144847231;done=true>>]
[junit4:junit4] 2> 821952 T2679 C725 P44787 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty4/index.20130604144847231
[junit4:junit4] 2> 821952 T2679 C725 P44787 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty4/index.20130604144847231
[junit4:junit4] 2> 821952 T2679 C725 P44787 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 821952 T2679 C725 P44787 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 821952 T2679 C725 P44787 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 821953 T2679 C725 P44787 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 821955 T2679 C725 P44787 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 822783 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 822784 T2608 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44787_lzph",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44787/lzph"}
[junit4:junit4] 2> 822822 T2659 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> 822822 T2607 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> 822822 T2676 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> 822822 T2643 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> 822822 T2627 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> 822822 T2614 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> 822924 T2585 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 822925 T2585 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C729 name=collection1 org.apache.solr.core.SolrCore@2f20f04c url=http://127.0.0.1:20484/lzph/collection1 node=127.0.0.1:20484_lzph C729_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:20484_lzph, base_url=http://127.0.0.1:20484/lzph, leader=true}
[junit4:junit4] 2> 822933 T2597 C729 P20484 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 822936 T2597 C729 P20484 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a762e09 lockFactory=org.apache.lucene.store.NativeFSLockFactory@21e48346),segFN=segments_1,generation=1}
[junit4:junit4] 2> 822937 T2597 C729 P20484 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 822937 T2597 C729 P20484 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a762e09 lockFactory=org.apache.lucene.store.NativeFSLockFactory@21e48346),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a762e09 lockFactory=org.apache.lucene.store.NativeFSLockFactory@21e48346),segFN=segments_2,generation=2}
[junit4:junit4] 2> 822938 T2597 C729 P20484 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 822938 T2597 C729 P20484 oass.SolrIndexSearcher.<init> Opening Searcher@3d39acce main
[junit4:junit4] 2> 822939 T2597 C729 P20484 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 822939 T2611 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3d39acce main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 822940 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 822950 T2637 C728 P57623 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 822951 T2637 C728 P57623 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ffa7477 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ac76779),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ffa7477 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ac76779),segFN=segments_3,generation=3}
[junit4:junit4] 2> 822951 T2637 C728 P57623 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 822952 T2637 C728 P57623 oass.SolrIndexSearcher.<init> Opening Searcher@3e4492 main
[junit4:junit4] 2> 822952 T2637 C728 P57623 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 822953 T2645 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3e4492 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 822954 T2637 C728 P57623 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:47919/lzph/collection1/, StdNode: http://127.0.0.1:16947/lzph/collection1/, StdNode: http://127.0.0.1:44787/lzph/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 822956 T2621 C727 P47919 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 822957 T2621 C727 P47919 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@239ddbcc lockFactory=org.apache.lucene.store.NativeFSLockFactory@7a39e08d),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@239ddbcc lockFactory=org.apache.lucene.store.NativeFSLockFactory@7a39e08d),segFN=segments_3,generation=3}
[junit4:junit4] 2> 822957 T2621 C727 P47919 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 822958 T2621 C727 P47919 oass.SolrIndexSearcher.<init> Opening Searcher@78e2c6fb main
[junit4:junit4] 2> 822958 T2621 C727 P47919 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 822959 T2629 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@78e2c6fb main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 822959 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 3
[junit4:junit4] 2> C725_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:44787_lzph, base_url=http://127.0.0.1:44787/lzph}
[junit4:junit4] 2> 822964 T2666 C725 P44787 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C726_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:16947_lzph, base_url=http://127.0.0.1:16947/lzph}
[junit4:junit4] 2> 822964 T2649 C726 P16947 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 822965 T2666 C725 P44787 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5b351311 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ede44c1),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5b351311 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ede44c1),segFN=segments_3,generation=3}
[junit4:junit4] 2> 822966 T2649 C726 P16947 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@71eae893 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b8a8eb7),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@71eae893 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b8a8eb7),segFN=segments_3,generation=3}
[junit4:junit4] 2> 822966 T2666 C725 P44787 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 822966 T2649 C726 P16947 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 822967 T2666 C725 P44787 oass.SolrIndexSearcher.<init> Opening Searcher@7b972d95 main
[junit4:junit4] 2> 822967 T2649 C726 P16947 oass.SolrIndexSearcher.<init> Opening Searcher@14756aa1 main
[junit4:junit4] 2> 822968 T2666 C725 P44787 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 822968 T2649 C726 P16947 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 822968 T2678 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7b972d95 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 822969 T2661 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@14756aa1 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 822969 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 822969 T2649 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 822970 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 20
[junit4:junit4] 2> 822971 T2585 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 822974 T2622 C727 P47919 oasc.SolrCore.execute [collection1] webapp=/lzph path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 822976 T2650 C726 P16947 oasc.SolrCore.execute [collection1] webapp=/lzph path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 822977 T2638 C728 P57623 oasc.SolrCore.execute [collection1] webapp=/lzph path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 822979 T2667 C725 P44787 oasc.SolrCore.execute [collection1] webapp=/lzph path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 824984 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436938907440644096)} 0 2
[junit4:junit4] 2> 824991 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={update.distrib=FROMLEADER&_version_=-1436938907445886976&update.from=http://127.0.0.1:57623/lzph/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436938907445886976)} 0 1
[junit4:junit4] 2> 824995 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={update.distrib=FROMLEADER&_version_=-1436938907449032704&update.from=http://127.0.0.1:47919/lzph/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436938907449032704)} 0 1
[junit4:junit4] 2> 824996 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1436938907449032704)} 0 6
[junit4:junit4] 2> 824996 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436938907445886976)} 0 9
[junit4:junit4] 2> 825000 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[a!0 (1436938907458469888)]} 0 1
[junit4:junit4] 2> 825005 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1436938907461615616)]} 0 0
[junit4:junit4] 2> 825006 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[a!0 (1436938907461615616)]} 0 4
[junit4:junit4] 2> 825009 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[b!1 (1436938907468955648)]} 0 0
[junit4:junit4] 2> 825013 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1436938907471052800)]} 0 0
[junit4:junit4] 2> 825014 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[b!1 (1436938907471052800)]} 0 3
[junit4:junit4] 2> 825017 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[c!2 (1436938907477344256)]} 0 0
[junit4:junit4] 2> 825022 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1436938907480489984)]} 0 0
[junit4:junit4] 2> 825023 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[c!2 (1436938907480489984)]} 0 3
[junit4:junit4] 2> 825025 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[d!3 (1436938907485732864)]} 0 0
[junit4:junit4] 2> 825031 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1436938907489927168)]} 0 0
[junit4:junit4] 2> 825032 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!3 (1436938907489927168)]} 0 3
[junit4:junit4] 2> 825033 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[d!3]} 0 5
[junit4:junit4] 2> 825035 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[e!4 (1436938907496218624)]} 0 0
[junit4:junit4] 2> 825040 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1436938907499364352)]} 0 0
[junit4:junit4] 2> 825041 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[e!4 (1436938907499364352)]} 0 3
[junit4:junit4] 2> 825043 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[f!5 (1436938907504607232)]} 0 0
[junit4:junit4] 2> 825050 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1436938907509850112)]} 0 0
[junit4:junit4] 2> 825051 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1436938907509850112)]} 0 3
[junit4:junit4] 2> 825051 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[f!5]} 0 5
[junit4:junit4] 2> 825054 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[g!6 (1436938907516141568)]} 0 0
[junit4:junit4] 2> 825059 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1436938907519287296)]} 0 0
[junit4:junit4] 2> 825060 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[g!6 (1436938907519287296)]} 0 3
[junit4:junit4] 2> 825062 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[h!7 (1436938907524530176)]} 0 0
[junit4:junit4] 2> 825069 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1436938907529773056)]} 0 0
[junit4:junit4] 2> 825070 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!7 (1436938907529773056)]} 0 3
[junit4:junit4] 2> 825070 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[h!7]} 0 5
[junit4:junit4] 2> 825073 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[i!8 (1436938907536064512)]} 0 0
[junit4:junit4] 2> 825078 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1436938907539210240)]} 0 0
[junit4:junit4] 2> 825079 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[i!8 (1436938907539210240)]} 0 3
[junit4:junit4] 2> 825081 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[j!9 (1436938907544453120)]} 0 0
[junit4:junit4] 2> 825088 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1436938907549696000)]} 0 0
[junit4:junit4] 2> 825089 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!9 (1436938907549696000)]} 0 3
[junit4:junit4] 2> 825089 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[j!9]} 0 5
[junit4:junit4] 2> 825092 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[k!10 (1436938907555987456)]} 0 0
[junit4:junit4] 2> 825097 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1436938907559133184)]} 0 0
[junit4:junit4] 2> 825098 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[k!10 (1436938907559133184)]} 0 3
[junit4:junit4] 2> 825100 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[l!11 (1436938907564376064)]} 0 0
[junit4:junit4] 2> 825107 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1436938907569618944)]} 0 0
[junit4:junit4] 2> 825108 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!11 (1436938907569618944)]} 0 3
[junit4:junit4] 2> 825108 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[l!11]} 0 5
[junit4:junit4] 2> 825111 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[m!12 (1436938907575910400)]} 0 0
[junit4:junit4] 2> 825118 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1436938907581153280)]} 0 0
[junit4:junit4] 2> 825119 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!12 (1436938907581153280)]} 0 3
[junit4:junit4] 2> 825119 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[m!12]} 0 5
[junit4:junit4] 2> 825122 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[n!13 (1436938907587444736)]} 0 0
[junit4:junit4] 2> 825127 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1436938907590590464)]} 0 0
[junit4:junit4] 2> 825128 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[n!13 (1436938907590590464)]} 0 3
[junit4:junit4] 2> 825130 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[o!14 (1436938907595833344)]} 0 0
[junit4:junit4] 2> 825135 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1436938907598979072)]} 0 0
[junit4:junit4] 2> 825136 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[o!14 (1436938907598979072)]} 0 3
[junit4:junit4] 2> 825143 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[p!15 (1436938907609464832)]} 0 5
[junit4:junit4] 2> 825149 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1436938907612610560)]} 0 0
[junit4:junit4] 2> 825150 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[p!15 (1436938907612610560)]} 0 4
[junit4:junit4] 2> 825152 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[q!16 (1436938907618902016)]} 0 0
[junit4:junit4] 2> 825157 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1436938907622047744)]} 0 0
[junit4:junit4] 2> 825158 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[q!16 (1436938907622047744)]} 0 3
[junit4:junit4] 2> 825160 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[r!17 (1436938907627290624)]} 0 0
[junit4:junit4] 2> 825168 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1436938907632533504)]} 0 0
[junit4:junit4] 2> 825169 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!17 (1436938907632533504)]} 0 4
[junit4:junit4] 2> 825170 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[r!17]} 0 7
[junit4:junit4] 2> 825172 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[s!18 (1436938907639873536)]} 0 0
[junit4:junit4] 2> 825179 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1436938907645116416)]} 0 0
[junit4:junit4] 2> 825180 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!18 (1436938907645116416)]} 0 3
[junit4:junit4] 2> 825180 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[s!18]} 0 5
[junit4:junit4] 2> 825183 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[t!19 (1436938907651407872)]} 0 0
[junit4:junit4] 2> 825188 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1436938907654553600)]} 0 0
[junit4:junit4] 2> 825189 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[t!19 (1436938907654553600)]} 0 3
[junit4:junit4] 2> 825191 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[u!20 (1436938907659796480)]} 0 0
[junit4:junit4] 2> 825196 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1436938907662942208)]} 0 0
[junit4:junit4] 2> 825197 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[u!20 (1436938907662942208)]} 0 3
[junit4:junit4] 2> 825199 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[v!21 (1436938907668185088)]} 0 0
[junit4:junit4] 2> 825206 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1436938907673427968)]} 0 0
[junit4:junit4] 2> 825207 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!21 (1436938907673427968)]} 0 3
[junit4:junit4] 2> 825207 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[v!21]} 0 5
[junit4:junit4] 2> 825210 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[w!22 (1436938907679719424)]} 0 0
[junit4:junit4] 2> 825215 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1436938907682865152)]} 0 0
[junit4:junit4] 2> 825216 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[w!22 (1436938907682865152)]} 0 3
[junit4:junit4] 2> 825218 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[x!23 (1436938907688108032)]} 0 0
[junit4:junit4] 2> 825225 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1436938907693350912)]} 0 0
[junit4:junit4] 2> 825226 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!23 (1436938907693350912)]} 0 3
[junit4:junit4] 2> 825226 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[x!23]} 0 5
[junit4:junit4] 2> 825229 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[y!24 (1436938907699642368)]} 0 0
[junit4:junit4] 2> 825234 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1436938907702788096)]} 0 0
[junit4:junit4] 2> 825235 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[y!24 (1436938907702788096)]} 0 3
[junit4:junit4] 2> 825237 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[z!25 (1436938907708030976)]} 0 0
[junit4:junit4] 2> 825244 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1436938907713273856)]} 0 0
[junit4:junit4] 2> 825245 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!25 (1436938907713273856)]} 0 3
[junit4:junit4] 2> 825245 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[z!25]} 0 5
[junit4:junit4] 2> 825248 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[a!26 (1436938907719565312)]} 0 0
[junit4:junit4] 2> 825253 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1436938907722711040)]} 0 0
[junit4:junit4] 2> 825254 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[a!26 (1436938907722711040)]} 0 3
[junit4:junit4] 2> 825256 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[b!27 (1436938907727953920)]} 0 0
[junit4:junit4] 2> 825261 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1436938907731099648)]} 0 0
[junit4:junit4] 2> 825262 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[b!27 (1436938907731099648)]} 0 3
[junit4:junit4] 2> 825264 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[c!28 (1436938907736342528)]} 0 0
[junit4:junit4] 2> 825271 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1436938907741585408)]} 0 0
[junit4:junit4] 2> 825272 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!28 (1436938907741585408)]} 0 3
[junit4:junit4] 2> 825272 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[c!28]} 0 5
[junit4:junit4] 2> 825275 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[d!29 (1436938907747876864)]} 0 0
[junit4:junit4] 2> 825282 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1436938907753119744)]} 0 0
[junit4:junit4] 2> 825283 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1436938907753119744)]} 0 3
[junit4:junit4] 2> 825283 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[d!29]} 0 5
[junit4:junit4] 2> 825286 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[e!30 (1436938907759411200)]} 0 0
[junit4:junit4] 2> 825293 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1436938907764654080)]} 0 0
[junit4:junit4] 2> 825294 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!30 (1436938907764654080)]} 0 3
[junit4:junit4] 2> 825294 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[e!30]} 0 5
[junit4:junit4] 2> 825297 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[f!31 (1436938907770945536)]} 0 0
[junit4:junit4] 2> 825304 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1436938907776188416)]} 0 0
[junit4:junit4] 2> 825305 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1436938907776188416)]} 0 3
[junit4:junit4] 2> 825305 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[f!31]} 0 5
[junit4:junit4] 2> 825308 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[g!32 (1436938907782479872)]} 0 0
[junit4:junit4] 2> 825315 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1436938907787722752)]} 0 0
[junit4:junit4] 2> 825316 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!32 (1436938907787722752)]} 0 3
[junit4:junit4] 2> 825316 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[g!32]} 0 5
[junit4:junit4] 2> 825319 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[h!33 (1436938907794014208)]} 0 0
[junit4:junit4] 2> 825326 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1436938907799257088)]} 0 0
[junit4:junit4] 2> 825327 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!33 (1436938907799257088)]} 0 3
[junit4:junit4] 2> 825327 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[h!33]} 0 5
[junit4:junit4] 2> 825330 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[i!34 (1436938907805548544)]} 0 0
[junit4:junit4] 2> 825335 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1436938907808694272)]} 0 0
[junit4:junit4] 2> 825336 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[i!34 (1436938907808694272)]} 0 3
[junit4:junit4] 2> 825338 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[j!35 (1436938907813937152)]} 0 0
[junit4:junit4] 2> 825345 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1436938907819180032)]} 0 0
[junit4:junit4] 2> 825346 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!35 (1436938907819180032)]} 0 3
[junit4:junit4] 2> 825346 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[j!35]} 0 5
[junit4:junit4] 2> 825349 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[k!36 (1436938907825471488)]} 0 0
[junit4:junit4] 2> 825356 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1436938907830714368)]} 0 0
[junit4:junit4] 2> 825357 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!36 (1436938907830714368)]} 0 3
[junit4:junit4] 2> 825357 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[k!36]} 0 5
[junit4:junit4] 2> 825360 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[l!37 (1436938907837005824)]} 0 0
[junit4:junit4] 2> 825365 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1436938907840151552)]} 0 0
[junit4:junit4] 2> 825366 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[l!37 (1436938907840151552)]} 0 3
[junit4:junit4] 2> 825368 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[m!38 (1436938907845394432)]} 0 0
[junit4:junit4] 2> 825375 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1436938907850637312)]} 0 0
[junit4:junit4] 2> 825376 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!38 (1436938907850637312)]} 0 3
[junit4:junit4] 2> 825376 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[m!38]} 0 5
[junit4:junit4] 2> 825379 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[n!39 (1436938907856928768)]} 0 0
[junit4:junit4] 2> 825384 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1436938907860074496)]} 0 0
[junit4:junit4] 2> 825385 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[n!39 (1436938907860074496)]} 0 3
[junit4:junit4] 2> 825387 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[o!40 (1436938907865317376)]} 0 0
[junit4:junit4] 2> 825394 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1436938907870560256)]} 0 0
[junit4:junit4] 2> 825395 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!40 (1436938907870560256)]} 0 3
[junit4:junit4] 2> 825395 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[o!40]} 0 5
[junit4:junit4] 2> 825398 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[p!41 (1436938907876851712)]} 0 0
[junit4:junit4] 2> 825405 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1436938907882094592)]} 0 0
[junit4:junit4] 2> 825406 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!41 (1436938907882094592)]} 0 3
[junit4:junit4] 2> 825406 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[p!41]} 0 5
[junit4:junit4] 2> 825409 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[q!42 (1436938907888386048)]} 0 0
[junit4:junit4] 2> 825414 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1436938907891531776)]} 0 0
[junit4:junit4] 2> 825415 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[q!42 (1436938907891531776)]} 0 3
[junit4:junit4] 2> 825417 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[r!43 (1436938907896774656)]} 0 0
[junit4:junit4] 2> 825422 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1436938907899920384)]} 0 0
[junit4:junit4] 2> 825423 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[r!43 (1436938907899920384)]} 0 3
[junit4:junit4] 2> 825425 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[s!44 (1436938907905163264)]} 0 0
[junit4:junit4] 2> 825432 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1436938907910406144)]} 0 0
[junit4:junit4] 2> 825433 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!44 (1436938907910406144)]} 0 3
[junit4:junit4] 2> 825433 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[s!44]} 0 5
[junit4:junit4] 2> 825436 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[t!45 (1436938907916697600)]} 0 0
[junit4:junit4] 2> 825441 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1436938907919843328)]} 0 0
[junit4:junit4] 2> 825442 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[t!45 (1436938907919843328)]} 0 3
[junit4:junit4] 2> 825444 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[u!46 (1436938907925086208)]} 0 0
[junit4:junit4] 2> 825449 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1436938907928231936)]} 0 0
[junit4:junit4] 2> 825450 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[u!46 (1436938907928231936)]} 0 3
[junit4:junit4] 2> 825452 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[v!47 (1436938907933474816)]} 0 0
[junit4:junit4] 2> 825457 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1436938907936620544)]} 0 0
[junit4:junit4] 2> 825458 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[v!47 (1436938907936620544)]} 0 3
[junit4:junit4] 2> 825460 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[w!48 (1436938907941863424)]} 0 0
[junit4:junit4] 2> 825465 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1436938907945009152)]} 0 0
[junit4:junit4] 2> 825466 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[w!48 (1436938907945009152)]} 0 3
[junit4:junit4] 2> 825468 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[x!49 (1436938907950252032)]} 0 0
[junit4:junit4] 2> 825475 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1436938907955494912)]} 0 0
[junit4:junit4] 2> 825476 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!49 (1436938907955494912)]} 0 3
[junit4:junit4] 2> 825476 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[x!49]} 0 5
[junit4:junit4] 2> 825479 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[y!50 (1436938907961786368)]} 0 0
[junit4:junit4] 2> 825484 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1436938907964932096)]} 0 0
[junit4:junit4] 2> 825485 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[y!50 (1436938907964932096)]} 0 3
[junit4:junit4] 2> 825487 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[z!51 (1436938907970174976)]} 0 0
[junit4:junit4] 2> 825492 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1436938907973320704)]} 0 0
[junit4:junit4] 2> 825493 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[z!51 (1436938907973320704)]} 0 3
[junit4:junit4] 2> 825495 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[a!52 (1436938907978563584)]} 0 0
[junit4:junit4] 2> 825500 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1436938907981709312)]} 0 0
[junit4:junit4] 2> 825501 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[a!52 (1436938907981709312)]} 0 3
[junit4:junit4] 2> 825503 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[b!53 (1436938907986952192)]} 0 0
[junit4:junit4] 2> 825510 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1436938907992195072)]} 0 0
[junit4:junit4] 2> 825511 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!53 (1436938907992195072)]} 0 3
[junit4:junit4] 2> 825511 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[b!53]} 0 5
[junit4:junit4] 2> 825514 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[c!54 (1436938907998486528)]} 0 0
[junit4:junit4] 2> 825521 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1436938908003729408)]} 0 0
[junit4:junit4] 2> 825522 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!54 (1436938908003729408)]} 0 3
[junit4:junit4] 2> 825522 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[c!54]} 0 5
[junit4:junit4] 2> 825525 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[d!55 (1436938908010020864)]} 0 0
[junit4:junit4] 2> 825530 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1436938908013166592)]} 0 0
[junit4:junit4] 2> 825531 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[d!55 (1436938908013166592)]} 0 3
[junit4:junit4] 2> 825533 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[e!56 (1436938908018409472)]} 0 0
[junit4:junit4] 2> 825540 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1436938908023652352)]} 0 0
[junit4:junit4] 2> 825541 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!56 (1436938908023652352)]} 0 3
[junit4:junit4] 2> 825541 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[e!56]} 0 5
[junit4:junit4] 2> 825544 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[f!57 (1436938908029943808)]} 0 0
[junit4:junit4] 2> 825549 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1436938908033089536)]} 0 0
[junit4:junit4] 2> 825550 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[f!57 (1436938908033089536)]} 0 3
[junit4:junit4] 2> 825552 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[g!58 (1436938908038332416)]} 0 0
[junit4:junit4] 2> 825557 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1436938908041478144)]} 0 0
[junit4:junit4] 2> 825558 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[g!58 (1436938908041478144)]} 0 3
[junit4:junit4] 2> 825560 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[h!59 (1436938908046721024)]} 0 0
[junit4:junit4] 2> 825565 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1436938908049866752)]} 0 0
[junit4:junit4] 2> 825566 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[h!59 (1436938908049866752)]} 0 3
[junit4:junit4] 2> 825568 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[i!60 (1436938908055109632)]} 0 0
[junit4:junit4] 2> 825573 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1436938908058255360)]} 0 0
[junit4:junit4] 2> 825574 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[i!60 (1436938908058255360)]} 0 3
[junit4:junit4] 2> 825576 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[j!61 (1436938908063498240)]} 0 0
[junit4:junit4] 2> 825583 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1436938908068741120)]} 0 0
[junit4:junit4] 2> 825584 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!61 (1436938908068741120)]} 0 3
[junit4:junit4] 2> 825584 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[j!61]} 0 5
[junit4:junit4] 2> 825587 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[k!62 (1436938908075032576)]} 0 0
[junit4:junit4] 2> 825592 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!62 (1436938908078178304)]} 0 0
[junit4:junit4] 2> 825593 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[k!62 (1436938908078178304)]} 0 3
[junit4:junit4] 2> 825595 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[l!63 (1436938908083421184)]} 0 0
[junit4:junit4] 2> 825602 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!63 (1436938908088664064)]} 0 0
[junit4:junit4] 2> 825603 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!63 (1436938908088664064)]} 0 3
[junit4:junit4] 2> 825603 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[l!63]} 0 5
[junit4:junit4] 2> 825606 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[m!64 (1436938908094955520)]} 0 0
[junit4:junit4] 2> 825613 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!64 (1436938908100198400)]} 0 0
[junit4:junit4] 2> 825614 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!64 (1436938908100198400)]} 0 3
[junit4:junit4] 2> 825614 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[m!64]} 0 5
[junit4:junit4] 2> 825617 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[n!65 (1436938908106489856)]} 0 0
[junit4:junit4] 2> 825622 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!65 (1436938908109635584)]} 0 0
[junit4:junit4] 2> 825623 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[n!65 (1436938908109635584)]} 0 3
[junit4:junit4] 2> 825625 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[o!66 (1436938908114878464)]} 0 0
[junit4:junit4] 2> 825632 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!66 (1436938908120121344)]} 0 0
[junit4:junit4] 2> 825633 T2639 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!66 (1436938908120121344)]} 0 3
[junit4:junit4] 2> 825633 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[o!66]} 0 5
[junit4:junit4] 2> 825636 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[p!67 (1436938908126412800)]} 0 0
[junit4:junit4] 2> 825641 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!67 (1436938908129558528)]} 0 0
[junit4:junit4] 2> 825642 T2623 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[p!67 (1436938908129558528)]} 0 3
[junit4:junit4] 2> 825644 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[q!68 (1436938908134801408)]} 0 0
[junit4:junit4] 2> 825651 T2651 C726 P16947 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:47919/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!68 (1436938908140044288)]} 0 0
[junit4:junit4] 2> 825652 T2621 C727 P47919 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!68 (1436938908140044288)]} 0 3
[junit4:junit4] 2> 825652 T2637 C728 P57623 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[q!68]} 0 5
[junit4:junit4] 2> 825655 T2597 C729 P20484 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={wt=javabin&version=2} {add=[r!69 (1436938908146335744)]} 0 0
[junit4:junit4] 2> 825662 T2666 C725 P44787 oasup.LogUpdateProcessor.finish [collection1] webapp=/lzph path=/update params={distrib.from=http://127.0.0.1:57623/lzph/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!69 (143
[...truncated too long message...]
1] CLOSING SolrCore org.apache.solr.core.SolrCore@77161026
[junit4:junit4] 2> 1008899 T2659 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=2,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=615,adds=615,deletesById=303,deletesByQuery=0,errors=0,cumulative_adds=674,cumulative_deletesById=303,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 1008899 T2659 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 1008899 T2659 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 1008900 T2659 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> ASYNC NEW_CORE C749 name=collection1 org.apache.solr.core.SolrCore@77161026 url=http://127.0.0.1:16947/lzph/collection1 node=127.0.0.1:16947_lzph C749_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:16947_lzph, base_url=http://127.0.0.1:16947/lzph}
[junit4:junit4] 2> 1008910 T2659 C749 P16947 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@71eae893 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b8a8eb7),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@71eae893 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b8a8eb7),segFN=segments_5,generation=5}
[junit4:junit4] 2> 1008910 T2659 C749 P16947 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 1008914 T2659 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1008914 T2659 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1008914 T2659 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3/index;done=false>>]
[junit4:junit4] 2> 1008914 T2659 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3/index
[junit4:junit4] 2> 1008915 T2659 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3;done=false>>]
[junit4:junit4] 2> 1008915 T2659 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1370371704398/jetty3
[junit4:junit4] 2> 1008915 T2659 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1008915 T2659 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard1/election/89808680019951626-4-n_0000000001
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:152)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:149)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:149)
[junit4:junit4] 2> at org.apache.solr.cloud.ElectionContext.cancelElection(ElectionContext.java:63)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:260)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> 1008916 T2659 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> 1008916 T2659 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1008916 T2659 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1008917 T2659 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> 1008917 T2659 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1008917 T2659 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=Pulsing41(freqCutoff=9 minBlockSize=63 maxBlockSize=199), _version_=Lucene41(blocksize=128), n_ti=PostingsFormat(name=Memory doPackFST= false)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=es_MX, timezone=Etc/GMT+4
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=2,free=229991264,total=308740096
[junit4:junit4] 2> NOTE: All tests run in this JVM: [PeerSyncTest, TermsComponentTest, QueryEqualityTest, SchemaVersionSpecificBehaviorTest, BadCopyFieldTest, TestSchemaResource, TestReloadAndDeleteDocs, CacheHeaderTest, SliceStateUpdateTest, TestManagedSchema, BasicFunctionalityTest, TestFieldCollectionResource, TestBadConfig, TestExtendedDismaxParser, QueryElevationComponentTest, TestPluginEnable, CoreAdminHandlerTest, DistributedTermsComponentTest, ZkCLITest, TestLFUCache, TestWriterPerf, CSVRequestHandlerTest, LeaderElectionTest, SliceStateTest, TestRandomDVFaceting, TestReplicationHandler, TestXIncludeConfig, TestPerFieldSimilarity, TestRealTimeGet, DirectSolrConnectionTest, TestLRUCache, TestTrie, TestFunctionQuery, RecoveryZkTest, TestPhraseSuggestions, AliasIntegrationTest, LukeRequestHandlerTest, TestUniqueKeyFieldResource, TermVectorComponentTest, TestSolrQueryParser, BinaryUpdateRequestHandlerTest, TestSchemaSimilarityResource, RegexBoostProcessorTest, ResourceLoaderTest, DocumentBuilderTest, TestPseudoReturnFields, DirectUpdateHandlerOptimizeTest, TestSurroundQueryParser, ShardRoutingTest, JsonLoaderTest, QueryResultKeyTest, TestLMDirichletSimilarityFactory, BasicDistributedZkTest, WordBreakSolrSpellCheckerTest, TestGroupingSearch, ShardSplitTest]
[junit4:junit4] Completed on J0 in 210.55s, 1 test, 1 error <<< FAILURES!
[...truncated 572 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:386: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:366: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:887: There were test failures: 297 suites, 1238 tests, 1 error, 13 ignored (7 assumptions)
Total time: 49 minutes 19 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure