I am running Apache/2.4.25 on FreeBSD install from ports. I have tried GET and HEAD... both with the request_status expression and the {hc('body') !~ /Maintenance/} on the check. When I check the access logs on the api1-7 servers... I never see it getting the requests. I can remove the status.php page... or put it in Maintenance Mode and it still shows Init Ok on the balancer-manager. Is there still a bug with the health checks inside virtual hosts definitions? I thought that was fixed in 2.4.24. Thanks Here is my virtual host config from the httpd.conf... <VirtualHost 192.168.1.89:8088> ProxyRequests Off ServerName host.example.com ProxyHCExpr ok23 {%{REQUEST_STATUS} =~ /^[23]/} ProxyHCExpr maint {hc('body') !~ /Maintenance/} <Proxy *> Order deny,allow Allow from all </Proxy> ProxyPass /balancer-manager ! ProxyPass /server-status ! ProxyPass / balancer://mycluster/ ProxyPassReverse / http://192.168.1.91/ ProxyPassReverse / http://192.168.1.92/ ProxyPassReverse / http://192.168.1.93/ ProxyPassReverse / http://192.168.1.94/ ProxyPassReverse / http://192.168.1.95/ ProxyPassReverse / http://192.168.1.96/ ProxyPassReverse / http://192.168.1.97/ <Proxy balancer://mycluster> ProxySet lbmethod=bybusyness BalancerMember http://192.168.1.91 route=api1 hcmethod=GET hcuri=/status.php hcexpr=ok23 hcinterval=10 BalancerMember http://192.168.1.92 route=api2 hcmethod=GET hcuri=/status.php hcexpr=ok23 hcinterval=10 BalancerMember http://192.168.1.93 route=api3 hcmethod=GET hcuri=/status.php hcexpr=ok23 hcinterval=10 BalancerMember http://192.168.1.94 route=api4 hcmethod=GET hcuri=/status.php hcexpr=ok23 hcinterval=10 BalancerMember http://192.168.1.95 route=api5 hcmethod=GET hcuri=/status.php hcexpr=ok23 hcinterval=10 BalancerMember http://192.168.1.96 route=api6 hcmethod=GET hcuri=/status.php hcexpr=ok23 hcinterval=10 BalancerMember http://192.168.1.97 route=api7 hcmethod=GET hcuri=/status.php hcexpr=ok23 hcinterval=10 </Proxy> <Location /balancer-manager> SetHandler balancer-manager Order deny,allow Allow from all </Location> </VirtualHost>
I would turn on debugging on the Apache httpd side and follow the error.log entries for the module. That will tell you when/if/how mod_proxy_hcheck is sending the requests and checking for health.
Ok I changed the LogLevel from warn to debug and did a apachectl restart. Here is what I get when I do a tail -f -n 10000 /var/log/httpd-error.log | grep -i hcheck [Thu Feb 23 07:47:15.466584 2017] [proxy_hcheck:debug] [pid 53928] mod_proxy_hcheck.c(994): AH03265: watchdog callback registered (_proxy_hcheck_) [Thu Feb 23 07:47:15.485753 2017] [proxy_hcheck:debug] [pid 53929] mod_proxy_hcheck.c(994): AH03265: watchdog callback registered (_proxy_hcheck_) [Thu Feb 23 07:47:15.485847 2017] [watchdog:debug] [pid 53929] mod_watchdog.c(513): AH02978: Watchdog: Looking for child (_proxy_hcheck_). [Thu Feb 23 07:47:15.486172 2017] [watchdog:debug] [pid 53929] mod_watchdog.c(538): AH02979: Watchdog: Created child worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.488651 2017] [watchdog:debug] [pid 53930] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.488753 2017] [watchdog:debug] [pid 53930] mod_watchdog.c(157): AH02972: Singleton Watchdog (_proxy_hcheck_) running [Thu Feb 23 07:47:15.488868 2017] [proxy_hcheck:debug] [pid 53930] mod_proxy_hcheck.c(857): AH03258: _proxy_hcheck_ watchdog started. [Thu Feb 23 07:47:15.489591 2017] [watchdog:debug] [pid 53931] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.494248 2017] [watchdog:debug] [pid 53932] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.494651 2017] [watchdog:debug] [pid 53933] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.494940 2017] [watchdog:debug] [pid 53934] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.494966 2017] [proxy_hcheck:debug] [pid 53930] mod_proxy_hcheck.c(871): AH03313: apr_thread_pool_create() with 16 threads succeeded [Thu Feb 23 07:47:15.495132 2017] [watchdog:debug] [pid 53935] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.496698 2017] [watchdog:debug] [pid 53936] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.497852 2017] [watchdog:debug] [pid 53937] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.498257 2017] [watchdog:debug] [pid 53938] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.498483 2017] [watchdog:debug] [pid 53939] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.499660 2017] [watchdog:debug] [pid 53940] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.500192 2017] [watchdog:debug] [pid 53941] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.500396 2017] [watchdog:debug] [pid 53943] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.501017 2017] [watchdog:debug] [pid 53944] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 07:47:15.500613 2017] [watchdog:debug] [pid 53942] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). I have been tailing the file for a few minutes now... and nothing else has been added to it. Thanks
Try the TRACE level just on mod_proxy_hcheck, but yeah, something looks wonky.
How do I enable TRACE on mod_proxy_hcheck?
You can do this in 2.4 via the per-module function described in https://httpd.apache.org/docs/2.4/logs.html eg LogLevel proxy_hcheck:TRACE2
Ok to help isolate the problem... 1. I put the proxy server in Maintenance Mode. So no traffic is being handled by the server. 2. I removed all health checks on the servers except 97 to try and keeps things easier to read. The logs look like the checks are being sent. [Thu Feb 23 08:52:37.805706 2017] [proxy_hcheck:trace2] [pid 45984] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 08:52:39.948377 2017] [proxy_hcheck:trace2] [pid 45984] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 08:52:42.094132 2017] [proxy_hcheck:trace2] [pid 45984] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 08:52:44.240959 2017] [proxy_hcheck:trace2] [pid 45984] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 08:52:46.380819 2017] [proxy_hcheck:trace2] [pid 45984] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. After I made that change and restarted Apache I also started a wireshark capture. And it confirms there is no traffic leaving the proxy going to .97 on those intervals.
Also enable for mod_proxy and watchdog
Like this? LogLevel proxy_hcheck:TRACE2 LogLevel proxy:TRACE2 LogLevel watchdog:TRACE2 or LogLevel proxy_hcheck:TRACE2 proxy:TRACE2 watchdog:TRACE2 Thanks
Both ways should work fine.
Ok added... LogLevel proxy_hcheck:TRACE2 LogLevel proxy:TRACE2 LogLevel watchdog:TRACE2 to the httpd.conf and restarted Apache. Here is the tail of the error.log file. [Thu Feb 23 11:08:41.443646 2017] [proxy:debug] [pid 48110] proxy_util.c(1819): AH00927: initializing worker proxy:reverse local [Thu Feb 23 11:08:41.443753 2017] [proxy:debug] [pid 48106] proxy_util.c(1870): AH00931: initialized single connection worker in child 48106 for (*) [Thu Feb 23 11:08:41.443816 2017] [proxy:debug] [pid 48099] proxy_util.c(1870): AH00931: initialized single connection worker in child 48099 for (*) [Thu Feb 23 11:08:41.443810 2017] [watchdog:debug] [pid 48109] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 11:08:41.443940 2017] [proxy:debug] [pid 48110] proxy_util.c(1870): AH00931: initialized single connection worker in child 48110 for (*) [Thu Feb 23 11:08:41.444049 2017] [proxy:debug] [pid 48109] proxy_util.c(1777): AH00925: initializing worker proxy:reverse shared [Thu Feb 23 11:08:41.444077 2017] [proxy:debug] [pid 48109] proxy_util.c(1819): AH00927: initializing worker proxy:reverse local [Thu Feb 23 11:08:41.444272 2017] [proxy:debug] [pid 48109] proxy_util.c(1870): AH00931: initialized single connection worker in child 48109 for (*) [Thu Feb 23 11:08:41.444367 2017] [watchdog:debug] [pid 48112] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 11:08:41.444413 2017] [watchdog:debug] [pid 48111] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 11:08:41.444536 2017] [proxy:debug] [pid 48112] proxy_util.c(1777): AH00925: initializing worker proxy:reverse shared [Thu Feb 23 11:08:41.444558 2017] [proxy:debug] [pid 48112] proxy_util.c(1819): AH00927: initializing worker proxy:reverse local [Thu Feb 23 11:08:41.444624 2017] [proxy:debug] [pid 48111] proxy_util.c(1777): AH00925: initializing worker proxy:reverse shared [Thu Feb 23 11:08:41.444646 2017] [proxy:debug] [pid 48111] proxy_util.c(1819): AH00927: initializing worker proxy:reverse local [Thu Feb 23 11:08:41.444662 2017] [proxy:debug] [pid 48112] proxy_util.c(1870): AH00931: initialized single connection worker in child 48112 for (*) [Thu Feb 23 11:08:41.444869 2017] [proxy:debug] [pid 48111] proxy_util.c(1870): AH00931: initialized single connection worker in child 48111 for (*) [Thu Feb 23 11:08:41.445051 2017] [watchdog:debug] [pid 48113] mod_watchdog.c(585): AH02981: Watchdog: Created worker thread (_proxy_hcheck_). [Thu Feb 23 11:08:41.445223 2017] [proxy:debug] [pid 48113] proxy_util.c(1777): AH00925: initializing worker proxy:reverse shared [Thu Feb 23 11:08:41.445244 2017] [proxy:debug] [pid 48113] proxy_util.c(1819): AH00927: initializing worker proxy:reverse local [Thu Feb 23 11:08:41.445320 2017] [proxy:debug] [pid 48113] proxy_util.c(1870): AH00931: initialized single connection worker in child 48113 for (*) [Thu Feb 23 11:08:43.518238 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:08:45.658571 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:08:47.797292 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:08:49.933575 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:08:52.079295 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:08:54.217768 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:08:56.362560 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:08:58.509137 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:00.650713 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:02.791724 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:04.926078 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:07.065940 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:09.211893 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:11.354459 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:13.515087 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:15.661700 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:17.802227 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:19.943065 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:22.086451 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:24.201581 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:26.346077 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:28.485516 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:30.626117 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:32.768680 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:34.910136 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:37.056353 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:39.194622 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:41.340963 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:43.481381 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:45.619863 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:47.762859 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog. [Thu Feb 23 11:09:49.905427 2017] [proxy_hcheck:trace2] [pid 48099] mod_proxy_hcheck.c(886): Run of _proxy_hcheck_ watchdog.
The Virtualhost itself is active, right? I am not seeing in the snippet where httpd is even creating the check workers... So far, have not been able to recreate here
Hold on... I think I can recreate... trying as we speak
Yep. Patched in trunk and proposed for backport. Thx for the report and the testing!
Awesome. Thanks
Any update on when we can expect this fix in 2.4.25 or newer version (2.4.26)? We have what appears to be the same exact problem. We cannot use mod_proxy_hcheck as the health check URI is not being called at all.
IIUC this bug has been backported to the 2.4.x branch with svn.apache.org/r1792905, so it should be easy to add it on top of 2.4.25. The next release (.26) should be out sometimes during the next couple of months (being conservative, might happen sooner).
I'm seeing this issue in httpd:2.4.29 docker image. It seems like no healthchecks are performed from balancers inside VirtualHost blocks. For instance the following triggers no healthckecks: Listen 12000 <VirtualHost *:12000> LogLevel proxy_hcheck:TRACE2 LogLevel proxy:TRACE2 LogLevel watchdog:TRACE2 LogLevel proxy_hcheck:TRACE2 LogLevel proxy:TRACE2 <Proxy balancer://mfapicluster> BalancerMember "http://somewhere0:10000" hcmethod=GET hcuri=/api/nodestatus hcinterval=1 hcpasses=1 hcfails=3 BalancerMember "http://somewhere1:10000" hcmethod=GET hcuri=/api/nodestatus hcinterval=1 hcpasses=1 hcfails=3 </Proxy> ProxyPass / balancer://mfapicluster/ ProxyPassReverse / balancer://mfapicluster/ </VirtualHost> where as this does: LogLevel proxy_hcheck:TRACE2 LogLevel proxy:TRACE2 LogLevel watchdog:TRACE2 LogLevel proxy_hcheck:TRACE2 LogLevel proxy:TRACE2 <Proxy balancer://mfapicluster> BalancerMember "http://somewhere0:10000" hcmethod=GET hcuri=/api/nodestatus hcinterval=1 hcpasses=1 hcfails=3 BalancerMember "http://somewhere1:10000" hcmethod=GET hcuri=/api/nodestatus hcinterval=1 hcpasses=1 hcfails=3 </Proxy> ProxyPass / balancer://mfapicluster/ ProxyPassReverse / balancer://mfapicluster/
Is this still an issue w/ later versions?
(In reply to Jim Jagielski from comment #18) > Is this still an issue w/ later versions? I have run into the exact same issue like Stefan on comment #17. No healthchecks happens from balancers inside virtualhost. I increased the TRACE level of mod_proxy_hcheck and in the logs I can see this: [Wed Feb 13 11:02:18.787838 2019] [proxy_hcheck:trace4] [pid 3589:tid 140626686764928] mod_proxy_hcheck.c(1035): AH10019: Missing unique per-server context: localhost.localdomain (13d94a8:139c5f8) (no hchecks) But if we add either ProxyHCExpr or ProxyHCTemplate, without necessarily use them, healthcheck works fine. I have tested it on latest version 2.4.38 and on 2.4.x branch.
Fixed by r1853560 in trunk, will propose a back port later.
Fixed in trunk only for now, setting the keyword.
This has been backported in 2.4.x in r1864000. This is part of 2.4.40.