[Impact]
The mod_proxy_hcheck module provides dynamic health checking of workers. The following error is encountered in jammy and kinetic when enabling mod_proxy_hcheck on some Apache2 nodes, which causes unusual behavior and is simply confusing.This is caused by the lack of a defined macro (PROXY_WORKER_IS_ERROR) and the lack of an operation on that in the source code. Fix is based on adding the missing part.
[Test Plan]
Make a container for testing:
$ lxc launch ubuntu-daily:jammy jammy-test
$ lxc shell jammy-test
Do the same 2 steps from above for kinetic:
$ lxc launch ubuntu-daily:kinetic kinetic-test
$ lxc shell kinetic-test
Type in the code from below inside both the kinetic and jammy containers:
# apt update && apt dist-upgrade -y
# apt install -y apache2 python3
# cat > /etc/apache2/sites-available/httpd-hcheck-initerr.conf << '__EOF__'
<VirtualHost *:80>
ServerAdmin <email address hidden>
DocumentRoot "/var/www/html"
ServerName myapp.example.com
ErrorLog "${APACHE_LOG_DIR}/myapp.example.com-error_log"
CustomLog "${APACHE_LOG_DIR}/myapp.example.com-access_log" common
ProxyPass / balancer://myapp stickysession=JSESSIONID
</VirtualHost>
__EOF__
# cat > /etc/apache2/conf-available/balancers.conf << '__EOF__'
<Proxy balancer://myapp>
BalancerMember http://127.0.0.1:8080/ route=app-route hcmethod=GET hcinterval=5 hcpasses=1 hcfails=1
</Proxy>
__EOF__
# a2enmod status
# a2enmod proxy
# a2enmod proxy_balancer
# a2enmod proxy_http
# a2enmod proxy_hcheck
# a2enmod lbmethod_byrequests
# a2enconf balancers
# a2ensite httpd-hcheck-initerr
# python3 -m http.server --bind 127.0.0.1 8080 &
# PYTHON_PID=$!
# systemctl restart apache2
# curl -s localhost/server-status?auto | grep ProxyBalancer | grep Status
# kill -9 $PYTHON_PID
# curl -s localhost -H 'host: myapp.example.com' -o /dev/null
# curl -s localhost/server-status?auto | grep ProxyBalancer | grep Status
# python3 -m http.server --bind 127.0.0.1 8080 &
# sleep 10
# curl -s localhost/server-status?auto | grep ProxyBalancer | grep Status
Example failed output:
Serving HTTP on 127.0.0.1 port 8080 (http://127.0.0.1:8080/) ...
ProxyBalancer[0]Worker[0]Status: Init Ok
scripts: line 6: 203609 Killed python3 -m http.server --bind 127.0.0.1 8080
ProxyBalancer[0]Worker[0]Status: Init Err
Serving HTTP on 127.0.0.1 port 8080 (http://127.0.0.1:8080/) ...
127.0.0.1 - - [18/Jan/2023 12:24:05] "GET / HTTP/1.0" 200 -
127.0.0.1 - - [18/Jan/2023 12:24:10] "GET / HTTP/1.0" 200 -
ProxyBalancer[0]Worker[0]Status: Init Err
Example of (expected) successful output:
Serving HTTP on 127.0.0.1 port 8080 (http://127.0.0.1:8080/) ...
ProxyBalancer[0]Worker[0]Status: Init Ok
scripts: line 6: 202190 Killed python3 -m http.server --bind 127.0.0.1 8080
ProxyBalancer[0]Worker[0]Status: Init Err
Serving HTTP on 127.0.0.1 port 8080 (http://127.0.0.1:8080/) ...
127.0.0.1 - - [18/Jan/2023 12:23:12] "GET / HTTP/1.0" 200 -
127.0.0.1 - - [18/Jan/2023 12:23:17] "GET / HTTP/1.0" 200 -
ProxyBalancer[0]Worker[0]Status: Init Ok
[Where problems could occur]
* The patch itself modifies the code of mod_proxy_hcheck, so any new bugs involving that module would be suspect.
* The patch changes the state of the workers, so issues cropping up that seem related to workers and its state could be suspect.
* Finally, since the patch modifies C code, issues typical of C code (segfaults, memory leaks, …) would be possible, however since this moves a chunk of code unmodified this seems unlikely.
* There may be a problem when a possible future fix introduces a discrepancy between the value between the defined MODULE_MAGIC_NUMBER_MINOR and the one describing the change. Simply, there might be an issue that comes from the values of the MODULE_MAGIC_NUMBER_MINOR.
----------------------------------------------------------------------
[Original Report]
While we were in the process of enabling mod_proxy_hcheck on some of our apache2 nodes we encountered an unusual behavior: sometimes, after rebooting a backend, its worker status remains marked as "Init Err" (balancer manager) until another request is made to the backend, no matter how many health checks complete successfully.
The following list shows the sequence of events leading to the problem:
1. Watchdog triggers health check, request is successful; worker status is "Init Ok"
2. HTTP request to apache2 with unreachable backend (rebooting); status becomes "Init Err"
3. Watchdog triggers another health check, request is again successful because the backend recovered; worker status remains "Init Err"
4. same as 3
5. same as 4
The only way for the worker status to recover is to wait for "hcfails" unsuccessful health checks and then again for "hcpasses" requests to be completed or just wait for legitimate traffic to retry the failed worker, which may not happen for a long time for rarely used applications.
This was surprising to us since we were expecting the worker status to be recovered after "hcpasses" successful health checks; however this doesn't seem to happen when the error status is triggered by ordinary traffic to the backend (i.e not health checks).
[Test Case]
# apt update && apt dist-upgrade -y
# apt install -y apache2 python3
# cat > /etc/apache2/sites-available/httpd-hcheck-initerr.conf << '__EOF__'
<VirtualHost *:80>
ServerAdmin <email address hidden>
DocumentRoot "/var/www/html"
ServerName myapp.example.com
ErrorLog "${APACHE_LOG_DIR}/myapp.example.com-error_log"
CustomLog "${APACHE_LOG_DIR}/myapp.example.com-access_log" common
ProxyPass / balancer://myapp stickysession=JSESSIONID
</VirtualHost>
__EOF__
# cat > /etc/apache2/conf-available/balancers.conf << '__EOF__'
<Proxy balancer://myapp>
BalancerMember http://127.0.0.1:8080/ route=app-route hcmethod=GET hcinterval=5 hcpasses=1 hcfails=1
</Proxy>
__EOF__
# a2enmod status
# a2enmod proxy
# a2enmod proxy_balancer
# a2enmod proxy_http
# a2enmod proxy_hcheck
# a2enmod lbmethod_byrequests
# a2enconf balancers
# a2ensite httpd-hcheck-initerr
# python3 -m http.server --bind 127.0.0.1 8080 &
# PYTHON_PID=$!
# systemctl restart apache2
# curl -s localhost/server-status?auto | grep ProxyBalancer | grep Status
# kill -9 $PYTHON_PID
# curl -s localhost -H 'host: myapp.example.com' -o /dev/null
# curl -s localhost/server-status?auto | grep ProxyBalancer | grep Status
# python3 -m http.server --bind 127.0.0.1 8080 &
# sleep 10
# curl -s localhost/server-status?auto | grep ProxyBalancer | grep Status
Example failed output:
Serving HTTP on 127.0.0.1 port 8080 (http://127.0.0.1:8080/) ...
ProxyBalancer[0]Worker[0]Status: Init Ok
scripts: line 6: 203609 Killed python3 -m http.server --bind 127.0.0.1 8080
ProxyBalancer[0]Worker[0]Status: Init Err
Serving HTTP on 127.0.0.1 port 8080 (http://127.0.0.1:8080/) ...
127.0.0.1 - - [18/Jan/2023 12:24:05] "GET / HTTP/1.0" 200 -
127.0.0.1 - - [18/Jan/2023 12:24:10] "GET / HTTP/1.0" 200 -
ProxyBalancer[0]Worker[0]Status: Init Err
Example of (expected) successful output:
Serving HTTP on 127.0.0.1 port 8080 (http://127.0.0.1:8080/) ...
ProxyBalancer[0]Worker[0]Status: Init Ok
scripts: line 6: 202190 Killed python3 -m http.server --bind 127.0.0.1 8080
ProxyBalancer[0]Worker[0]Status: Init Err
Serving HTTP on 127.0.0.1 port 8080 (http://127.0.0.1:8080/) ...
127.0.0.1 - - [18/Jan/2023 12:23:12] "GET / HTTP/1.0" 200 -
127.0.0.1 - - [18/Jan/2023 12:23:17] "GET / HTTP/1.0" 200 -
ProxyBalancer[0]Worker[0]Status: Init Ok
Upstream bug: https://bz.apache.org/bugzilla/show_bug.cgi?id=66302
Upstream fix: https://svn.apache.org/viewvc?view=revision&revision=1906496
We would like to see this fix backported in Jammy.
Created attachment 38407
mod_proxy_hcheck: recover worker from error state
While we were in the process of enabling mod_proxy_hcheck on some of our apache2 nodes we encountered an unusual behavior: sometimes, after rebooting a backend, its worker status remains marked as "Init Err" (balancer manager) until another request is made to the backend, no matter how many health checks complete successfully.
The following list shows the sequence of events leading to the problem:
1. Watchdog triggers health check, request is successful; worker status is "Init Ok"
2. HTTP request to apache2 with unreachable backend (rebooting); status becomes "Init Err"
3. Watchdog triggers another health check, request is again successful because the backend recovered; worker status remains "Init Err"
4. same as 3
5. same as 4
The only way for the worker status to recover is to wait for "hcfails" unsuccessful health checks and then again for "hcpasses" requests to be completed or just wait for legitimate traffic to retry the failed worker, which may not happen for a long time for rarely used applications.
This was surprising to us since we were expecting the worker status to be recovered after "hcpasses" successful health checks; however this doesn't seem to happen when the error status is triggered by ordinary traffic to the backend (i.e not health checks).
We believe this behavior was accidentally introduced in r1725523. The patch we are proposing seems to fix the problem in our environment.