OSDir

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

[Bug 62318] New: healthcheck executed more often than configured in hcinterval


https://bz.apache.org/bugzilla/show_bug.cgi?id=62318

            Bug ID: 62318
           Summary: healthcheck executed more often than configured in
                    hcinterval
           Product: Apache httpd-2
           Version: 2.4.33
          Hardware: PC
                OS: Linux
            Status: NEW
          Severity: normal
          Priority: P2
         Component: mod_proxy_hcheck
          Assignee: bugs@xxxxxxxxxxxxxxxx
          Reporter: andreas.herold@xxxxxx
  Target Milestone: ---

I'm using following configuration, expecting that one health-check will be
executed every 10 seconds on each balancer member.

#---------------

# make sure, not to act as forward proxy
ProxyRequests Off

# do not rewrite Host-Header when forwarding request
ProxyPreserveHost on

# define proxy with balancer-members and settings
<Proxy balancer://omscluster>
    BalancerMember http://10.0.29.90:8180 max=5 timeout=70 retry=40
acquire=30000 route=jdevoms36.rnd.j.intershop.de_frontend hcmethod=GET
hcinterval=10 hcuri=/monitoring/services/health/status
    BalancerMember http://10.0.29.96:8180 max=5 timeout=70 retry=40
acquire=30000 route=jdevoms37.rnd.j.intershop.de_frontend hcmethod=GET
hcinterval=10 hcuri=/monitoring/services/health/status
    ProxySet lbmethod=bybusyness
</Proxy>

# enable balancer-manager, avoid proxying
<Location /balancer-manager>
  SetHandler balancer-manager
  ProxyPass !
  AuthType Basic
  AuthUserFile "/opt/httpd/conf/htpasswd"
  AuthName "admin"
  require valid-user
</Location>

# proxying everything else
ProxyPass / balancer://omscluster/ stickysession=JSESSIONID
ProxyPassReverse / balancer://omscluster/ stickysession=JSESSIONID

#------------------------

I have enabled tracing, resulting log looks like this.

[root@jdevoms29 httpd]# tail -f logs/error_log.2018-04-20_11_CET |grep
'mod_watchdog'
[Fri Apr 20 13:44:10.001381 2018] [watchdog:debug] [pid 11386:tid
139841708402496] mod_watchdog.c(454): AH010033: Watchdog: Running with
WatchdogInterval 1000ms
[Fri Apr 20 13:44:10.001393 2018] [watchdog:debug] [pid 11386:tid
139841708402496] mod_watchdog.c(462): AH02974: Watchdog: found parent
providers.
[Fri Apr 20 13:44:10.001407 2018] [watchdog:debug] [pid 11386:tid
139841708402496] mod_watchdog.c(508): AH02977: Watchdog: found child providers.
[Fri Apr 20 13:44:10.001415 2018] [watchdog:debug] [pid 11386:tid
139841708402496] mod_watchdog.c(516): AH02978: Watchdog: Looking for child
(_singleton_).
[Fri Apr 20 13:44:10.001425 2018] [watchdog:debug] [pid 11386:tid
139841708402496] mod_watchdog.c(516): AH02978: Watchdog: Looking for child
(_default_).
[Fri Apr 20 13:44:10.001435 2018] [watchdog:debug] [pid 11386:tid
139841708402496] mod_watchdog.c(516): AH02978: Watchdog: Looking for child
(_proxy_hcheck_).
[Fri Apr 20 13:44:10.001473 2018] [watchdog:debug] [pid 11386:tid
139841708402496] mod_watchdog.c(541): AH02979: Watchdog: Created child worker
thread (_proxy_hcheck_).
[Fri Apr 20 13:44:10.016816 2018] [watchdog:debug] [pid 11389:tid
139841598105344] mod_watchdog.c(158): AH02972: Singleton Watchdog
(_proxy_hcheck_) running
[Fri Apr 20 13:44:10.017861 2018] [watchdog:debug] [pid 11389:tid
139841708402496] mod_watchdog.c(588): AH02981: Watchdog: Created worker thread
(_proxy_hcheck_).
[Fri Apr 20 13:44:10.018537 2018] [watchdog:debug] [pid 11390:tid
139841708402496] mod_watchdog.c(588): AH02981: Watchdog: Created worker thread
(_proxy_hcheck_).
[Fri Apr 20 13:44:10.019052 2018] [watchdog:debug] [pid 11391:tid
139841708402496] mod_watchdog.c(588): AH02981: Watchdog: Created worker thread
(_proxy_hcheck_).
[Fri Apr 20 13:44:15.014163 2018] [watchdog:debug] [pid 11493:tid
139841708402496] mod_watchdog.c(588): AH02981: Watchdog: Created worker thread
(_proxy_hcheck_).
^C
[root@jdevoms29 httpd]# tail -f logs/error_log.2018-04-20_11_CET |grep
'AH03256: Threaded Health checking'
[Fri Apr 20 13:45:30.208536 2018] [proxy_hcheck:debug] [pid 11389:tid
139841484338944] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:45:30.208813 2018] [proxy_hcheck:debug] [pid 11389:tid
139841475946240] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.96:8180
[Fri Apr 20 13:45:30.308718 2018] [proxy_hcheck:debug] [pid 11389:tid
139841492731648] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.96:8180
[Fri Apr 20 13:45:40.237689 2018] [proxy_hcheck:debug] [pid 11389:tid
139841450768128] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:45:40.237948 2018] [proxy_hcheck:debug] [pid 11389:tid
139841392019200] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.96:8180
[Fri Apr 20 13:45:50.269505 2018] [proxy_hcheck:debug] [pid 11389:tid
139841517909760] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:45:50.269814 2018] [proxy_hcheck:debug] [pid 11389:tid
139841459160832] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.96:8180
[Fri Apr 20 13:45:50.369765 2018] [proxy_hcheck:debug] [pid 11389:tid
139841425590016] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:46:00.330515 2018] [proxy_hcheck:debug] [pid 11389:tid
139841408804608] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:46:00.330745 2018] [proxy_hcheck:debug] [pid 11389:tid
139841442375424] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.96:8180
[Fri Apr 20 13:46:00.430916 2018] [proxy_hcheck:debug] [pid 11389:tid
139841417197312] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.96:8180
[Fri Apr 20 13:46:00.531037 2018] [proxy_hcheck:debug] [pid 11389:tid
139841467553536] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.96:8180
[Fri Apr 20 13:46:10.368412 2018] [proxy_hcheck:debug] [pid 11389:tid
139841433982720] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:46:10.368601 2018] [proxy_hcheck:debug] [pid 11389:tid
139841501124352] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.96:8180
[Fri Apr 20 13:46:20.416752 2018] [proxy_hcheck:debug] [pid 11389:tid
139841509517056] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:46:20.416934 2018] [proxy_hcheck:debug] [pid 11389:tid
139841400411904] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.96:8180
[Fri Apr 20 13:46:20.516910 2018] [proxy_hcheck:debug] [pid 11389:tid
139841484338944] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:46:20.617105 2018] [proxy_hcheck:debug] [pid 11389:tid
139841492731648] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:46:20.717236 2018] [proxy_hcheck:debug] [pid 11389:tid
139841475946240] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:46:30.462732 2018] [proxy_hcheck:debug] [pid 11389:tid
139841450768128] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:46:30.463110 2018] [proxy_hcheck:debug] [pid 11389:tid
139841392019200] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.96:8180
[Fri Apr 20 13:46:30.562857 2018] [proxy_hcheck:debug] [pid 11389:tid
139841459160832] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.96:8180
[Fri Apr 20 13:46:40.499302 2018] [proxy_hcheck:debug] [pid 11389:tid
139841425590016] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:46:40.499494 2018] [proxy_hcheck:debug] [pid 11389:tid
139841517909760] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.96:8180
[Fri Apr 20 13:46:50.530944 2018] [proxy_hcheck:debug] [pid 11389:tid
139841408804608] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:46:50.531195 2018] [proxy_hcheck:debug] [pid 11389:tid
139841417197312] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.96:8180
[Fri Apr 20 13:46:50.631150 2018] [proxy_hcheck:debug] [pid 11389:tid
139841467553536] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:46:50.731319 2018] [proxy_hcheck:debug] [pid 11389:tid
139841442375424] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:46:50.831512 2018] [proxy_hcheck:debug] [pid 11389:tid
139841433982720] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:46:50.931690 2018] [proxy_hcheck:debug] [pid 11389:tid
139841501124352] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180
[Fri Apr 20 13:46:51.031958 2018] [proxy_hcheck:debug] [pid 11389:tid
139841400411904] mod_proxy_hcheck.c(822): AH03256: Threaded Health checking
http://10.0.29.90:8180

The tracing shows only few more health-checks than configured. But identical
configuration produced much more health-checks before. Unfortunately I have
only access-logs of balancer member.

10.0.29.32 - - [16/Mar/2018:17:02:47 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 681 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 48 application/json
10.0.29.32 - - [16/Mar/2018:17:02:47 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 967 application/json
10.0.29.32 - - [16/Mar/2018:17:02:47 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 200 518 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 1229 application/json
10.0.29.32 - - [16/Mar/2018:17:02:47 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 792 application/json
10.0.29.32 - - [16/Mar/2018:17:02:47 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 681 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 41 application/json
10.0.29.32 - - [16/Mar/2018:17:02:47 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 1104 application/json
10.0.29.32 - - [16/Mar/2018:17:02:47 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 681 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 81 application/json
10.0.29.32 - - [16/Mar/2018:17:02:47 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 833 application/json
10.0.29.32 - - [16/Mar/2018:17:02:47 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 200 518 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 1062 application/json
10.0.29.32 - - [16/Mar/2018:17:02:47 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 681 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 43 application/json
10.0.29.32 - - [16/Mar/2018:17:02:47 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 681 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 54 application/json
10.0.29.32 - - [16/Mar/2018:17:02:47 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 681 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 53 application/json
10.0.29.32 - - [16/Mar/2018:17:02:47 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 1076 application/json
10.0.29.32 - - [16/Mar/2018:17:02:48 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 639 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 386 application/json
10.0.29.32 - - [16/Mar/2018:17:02:48 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 200 518 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 1638 application/json
10.0.29.32 - - [16/Mar/2018:17:02:48 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 681 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 191 application/json
10.0.29.32 - - [16/Mar/2018:17:02:48 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 681 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 83 application/json
10.0.29.32 - - [16/Mar/2018:17:02:48 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 1121 application/json
10.0.29.32 - - [16/Mar/2018:17:02:48 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 597 application/json
10.0.29.32 - - [16/Mar/2018:17:02:48 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 373 application/json
10.0.29.32 - - [16/Mar/2018:17:02:49 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 386 application/json
10.0.29.32 - - [16/Mar/2018:17:02:49 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 200 518 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 2119 application/json
10.0.29.32 - - [16/Mar/2018:17:02:49 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 200 518 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 2144 application/json
10.0.29.32 - - [16/Mar/2018:17:02:49 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 200 518 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 1781 application/json
10.0.29.32 - - [16/Mar/2018:17:02:49 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 200 518 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 2085 application/json
10.0.29.32 - - [16/Mar/2018:17:02:49 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 639 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 1125 application/json
10.0.29.32 - - [16/Mar/2018:17:02:49 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 200 518 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 1526 application/json
10.0.29.32 - - [16/Mar/2018:17:02:49 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 200 518 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 801 application/json
10.0.29.32 - - [16/Mar/2018:17:02:49 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 681 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 94 application/json
10.0.29.32 - - [16/Mar/2018:17:02:49 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 700 application/json
10.0.29.32 - - [16/Mar/2018:17:02:50 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 681 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 64 application/json
10.0.29.32 - - [16/Mar/2018:17:02:50 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 953 application/json
10.0.29.32 - - [16/Mar/2018:17:02:50 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 988 application/json
10.0.29.32 - - [16/Mar/2018:17:02:50 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 962 application/json
10.0.29.32 - - [16/Mar/2018:17:02:50 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 1181 application/json
10.0.29.32 - - [16/Mar/2018:17:02:50 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 200 518 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 1282 application/json
10.0.29.32 - - [16/Mar/2018:17:02:50 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 1172 application/json
10.0.29.32 - - [16/Mar/2018:17:02:50 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 503 635 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 1204 application/json
10.0.29.32 - - [16/Mar/2018:17:02:51 +0100] 'GET
/monitoring/services/health/status HTTP/1.0' 200 518 '-' '-' '10.0.29.90:8180'
'-' 10.0.29.90 8180 HTTP/1.0 1120 application/json

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@xxxxxxxxxxxxxxxx
For additional commands, e-mail: bugs-help@xxxxxxxxxxxxxxxx