Bug 1051446

Summary:	[origin_cartridge_101]Gear-up will be triggered twice continuously when apache benchmark to send multiple requests to haproxy
Product:	OpenShift Online	Reporter:	Lei Zhang <lzhang>
Component:	Image	Assignee:	Dan McPherson <dmcphers>
Status:	CLOSED CURRENTRELEASE	QA Contact:	libra bugs <libra-bugs>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	2.x	CC:	bmeng, xtian
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2014-01-30 00:55:13 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Lei Zhang 2014-01-10 10:00:46 UTC

Description of problem:
Give one scalable app created(e.g.,mypython26s), use command 'ab' to send multiple request to haproxy with 20 sessions from instance, found gear-up will be triggered twice.


--------------Check haproxy/logs/scale_events.log-----------------------
D, [2014-01-10T02:13:20.941812 #21672] DEBUG -- : Local sessions 13
D, [2014-01-10T02:13:20.941980 #21672] DEBUG -- : Got stats from 0 remote proxies.
D, [2014-01-10T02:13:20.945680 #21672] DEBUG -- : Local sessions 15
D, [2014-01-10T02:13:20.945762 #21672] DEBUG -- : Got stats from 0 remote proxies.
D, [2014-01-10T02:13:20.945876 #21672] DEBUG -- : GEAR_INFO - capacity: 93.75% gear_count: 1 sessions: 15 up/remove_thresh: 90.0%/1.0% sec_left_til_remove: 530 gear_remove_thresh: 0/20
D, [2014-01-10T02:13:26.003736 #21672] DEBUG -- : Local sessions 16
D, [2014-01-10T02:13:26.003883 #21672] DEBUG -- : Got stats from 0 remote proxies.
I, [2014-01-10T02:13:26.004014 #21672]  INFO -- : GEAR_UP - capacity: 100.0% gear_count: 1 sessions: 16 up_thresh: 90.0%
I, [2014-01-10T02:14:52.276431 #23662]  INFO -- : Starting haproxy_ctld
I, [2014-01-10T02:14:57.349468 #23662]  INFO -- : GEAR_UP - capacity: 100.0% gear_count: 1 sessions: 16 up_thresh: 90.0%
D, [2014-01-10T02:15:40.503400 #24393] DEBUG -- : Local sessions 0
D, [2014-01-10T02:15:40.508440 #24393] DEBUG -- : Got stats from 0 remote proxies.
I, [2014-01-10T02:15:40.508666 #24393]  INFO -- : Starting haproxy_ctld
D, [2014-01-10T02:15:40.510103 #24393] DEBUG -- : Local sessions 0
D, [2014-01-10T02:15:40.517605 #24393] DEBUG -- : Got stats from 0 remote proxies.
D, [2014-01-10T02:15:40.517849 #24393] DEBUG -- : GEAR_INFO - capacity: 0.0% gear_count: 1 sessions: 0 up/remove_thresh: 90.0%/1.0% sec_left_til_remove: 600 gear_remove_thresh: 0/20

Version-Release number of selected component (if applicable):
devenv_4205 

How reproducible:
always

Steps to Reproduce:
1.Create one scalable app
#rhc app create mypython26s python-2.6 -s 
2.use 'ab' to send multiple request to haproxy from instance.
#ab -n 2000000 -c 20 http://mypython26s-chunchen.dev.rhcloud.com/
3.

Actual results:
Gear-up has been triggered twice continuously when ab send multiple request more than session threshold 

Expected results:
Gear-up should just trigger once when ab send multiple request more than session threshold

Additional info:

Comment 1 Meng Bo 2014-01-10 10:41:34 UTC

Not only scale-up, the GEAR_UP event will come by following a GEAR_DOWN as well.

D, [2014-01-10T05:13:15.277575 #21181] DEBUG -- : Local sessions 18
D, [2014-01-10T05:13:15.277823 #21181] DEBUG -- : Got stats from 0 remote proxies.
D, [2014-01-10T05:13:15.278942 #21181] DEBUG -- : Local sessions 18
D, [2014-01-10T05:13:15.279085 #21181] DEBUG -- : Got stats from 0 remote proxies.
D, [2014-01-10T05:13:15.279252 #21181] DEBUG -- : GEAR_INFO - capacity: 37.5% gear_count: 3 sessions: 18 up/remove_thresh: 90.0%/55.5% sec_left_til_remove: 0 gear_remove_thresh: 19/20
D, [2014-01-10T05:13:20.300121 #21181] DEBUG -- : Local sessions 21
D, [2014-01-10T05:13:20.300304 #21181] DEBUG -- : Got stats from 0 remote proxies.
I, [2014-01-10T05:13:20.300820 #21181]  INFO -- : GEAR_DOWN - capacity: 43.75% gear_count: 3 sessions: 21 remove_thresh: 55.5%
I, [2014-01-10T05:13:51.050617 #22774]  INFO -- : Starting haproxy_ctld
I, [2014-01-10T05:13:51.065531 #22774]  INFO -- : GEAR_UP - capacity: 93.75% gear_count: 3 sessions: 45 up_thresh: 90.0%
D, [2014-01-10T05:14:36.044367 #23500] DEBUG -- : Local sessions 45
D, [2014-01-10T05:14:36.051699 #23500] DEBUG -- : Got stats from 0 remote proxies.
I, [2014-01-10T05:14:36.051838 #23500]  INFO -- : Starting haproxy_ctld
D, [2014-01-10T05:14:36.056327 #23500] DEBUG -- : Local sessions 45
D, [2014-01-10T05:14:36.056481 #23500] DEBUG -- : Got stats from 0 remote proxies.
D, [2014-01-10T05:14:36.056884 #23500] DEBUG -- : GEAR_INFO - capacity: 140.625% gear_count: 2 sessions: 45 up/remove_thresh: 90.0%/40.5% sec_left_til_remove: 60 gear_remove_thresh: 0/20

Comment 2 Dan McPherson 2014-01-10 15:29:10 UTC

The issue here is all the 

Starting haproxy_ctld

lines.  There should only be 1 of those.  I am digging into why so many are being started.

Comment 3 Dan McPherson 2014-01-13 01:54:56 UTC

https://github.com/openshift/origin-server/pull/4457

Comment 4 openshift-github-bot 2014-01-13 02:48:20 UTC

Commit pushed to master at https://github.com/openshift/origin-server

https://github.com/openshift/origin-server/commit/05d52c0b06301d6e24b5ac1a31cd107ff16e31c2
Bug 1051446

Comment 5 Lei Zhang 2014-01-13 11:53:06 UTC

Verified on devenv_4214



, [2014-01-13T05:58:21.605784 #8432] DEBUG -- : Local sessions 15
D, [2014-01-13T05:58:21.605887 #8432] DEBUG -- : Got stats from 0 remote proxies.
D, [2014-01-13T05:58:21.605991 #8432] DEBUG -- : GEAR_INFO - capacity: 93.75% gear_count: 1 sessions: 15 up/remove_thresh: 90.0%/1.0% sec_left_til_remove: 570 gear_remove_thresh: 0/20
D, [2014-01-13T05:58:26.608377 #8432] DEBUG -- : Local sessions 17
D, [2014-01-13T05:58:26.608509 #8432] DEBUG -- : Got stats from 0 remote proxies.
I, [2014-01-13T05:58:26.608633 #8432]  INFO -- : add-gear - capacity: 106.25% gear_count: 1 sessions: 17 up_thresh: 90.0%
I, [2014-01-13T06:00:11.914086 #8432]  INFO -- : add-gear - exit_code: 0  output: 
D, [2014-01-13T06:00:11.920485 #8432] DEBUG -- : Local sessions 18
D, [2014-01-13T06:00:11.920595 #8432] DEBUG -- : Got stats from 0 remote proxies.
D, [2014-01-13T06:00:11.920728 #8432] DEBUG -- : GEAR_INFO - capacity: 56.25% gear_count: 2 sessions: 18 up/remove_thresh: 90.0%/40.5% sec_left_til_remove: 495 gear_remove_thresh: 0/20
D, [2014-01-13T06:00:11.922332 #8432] DEBUG -- : Local sessions 18
D, [2014-01-13T06:00:11.922417 #8432] DEBUG -- : Got stats from 0 remote proxies.
D, [2014-01-13T06:00:11.922512 #8432] DEBUG -- : GEAR_INFO - capacity: 56.25% gear_count: 2 sessions: 18 up/remove_thresh: 90.0%/40.5% sec_left_til_remove: 495 gear_remove_thresh: 0/20
D, [2014-01-13T06:00:16.933261 #8432] DEBUG -- : Local sessions 18
D, [2014-01-13T06:00:16.933465 #8432] DEBUG -- : Got stats from 0 remote proxies.