From 711c670319af662cc27a0641a01f11a5c8105a46 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 22 Aug 2026 10:10:59 -0700 Subject: [PATCH] fix(logging): stop silently discarding every access log line haproxy.cfg's global section has had `log 127.0.0.1 local2` since day one. That is the CONTAINER's own loopback: nothing has ever listened on udp/514 in the container netns and there is no /dev/log in the image. Every access log line -- ~1.5M/day across ~60 customer sites -- was written to a socket with no receiver and dropped. Nothing errored, nothing warned, and `haproxy -c` was perfectly happy, so this survived unnoticed. The cost only shows up during an incident. Per-IP 429s, tarpits, wp-admin gate redirects, WAF 403s and `silent-drop`s left no record anywhere, so the edge could not be asked what it had actually rejected -- only aggregate stick-table counters survived. That blind spot applies to every WHP host. Changes: * hap_header.tpl: point `log` at {{ syslog_target }} (default 172.18.0.1:514, the client-net bridge gateway) with `len 2048 format rfc5424 local2 info`. WHP's setup-haproxy-syslog.sh installs the matching rsyslog receiver on the host, in a dedicated ruleset ending in stop() so 1.5M lines/day cannot flood /var/log/messages or the Graylog forwarder, bound to the bridge IP rather than 0.0.0.0. * haproxy_manager.py: render that target from HAPROXY_SYSLOG_TARGET so standalone/home deployments on a different bridge subnet can retarget it. * hap_listener.tpl: add a frontend-scoped `log-format`. `option httplog` is not sufficient for incident response -- it omits %ID entirely (verified against 3.0.11), and its %ci is the Cloudflare edge rather than the visitor for CF-fronted sites. The new format keeps the first 16 fields byte-identical to the httplog default (so existing parsers still work) and appends cip=, id=, host=, ua=, sni=, hv=. Adds a User-Agent capture in slot 1 to feed it. * hap_header.tpl: correct the comment claiming `option httplog` includes %ID. It does not, which made the documented support-correlation workflow (X-Request-Reference -> access log -> coraza audit.log -> rule_id) look supported when it could never have worked. Deliberately NOT using `log stdout format raw local0`: it is incompatible with the `daemon` keyword, and incompatible SILENTLY. Verified on the pinned 3.0.11 binary -- with `daemon` set, a `log stdout` config serves traffic normally and emits zero log lines, while `haproxy -c` returns 0 with no error and no warning, so scripts/validate-rendered-config.py could not catch it either. Making it work would mean dropping `daemon`, which breaks the three synchronous `subprocess.run(['haproxy', '-W', ...], check=True)` launch sites in haproxy_manager.py -- the exact code path whose failure mode is "container Up, ports 80/443 never bound, every site down, /health still 200". UDP was chosen so a dead listener degrades to dropped log lines rather than a stalled request path. Verified: scripts/validate-rendered-config.py passes `haproxy -c` on both the "default" and "full" scenarios against the real 3.0.11 binary; and a live haproxy running WITH `daemon` (as production does) was confirmed to emit real lines carrying the true client IP from CF-Connecting-IP: <150>1 2026-08-22T17:05:21+00:00 - haproxy 109 - - 127.0.0.1:51194 [22/Aug/2026:17:05:21.217] t t/ 0/-1/-1/-1/0 200 73 - - LR-- 1/1/0/0/0 0/0 {cf-site.example|Mozilla/5.0 RealVisitor} "GET /checkout/ HTTP/1.1" cip=203.0.113.77 id=dfe94fa9-8d95-4126-81e1-821578f22872 host=cf-site.example ua=Mozilla/5.0 RealVisitor sni=- hv=1 Co-Authored-By: Claude Opus 5 (1M context) --- VERSION | 2 +- haproxy_manager.py | 11 ++++++++ templates/hap_header.tpl | 52 ++++++++++++++++++++++++++++++-------- templates/hap_listener.tpl | 37 ++++++++++++++++++++++++++- 4 files changed, 89 insertions(+), 13 deletions(-) diff --git a/VERSION b/VERSION index ebe6af6..f1498dc 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -2026.08.6 +2026.08.7 diff --git a/haproxy_manager.py b/haproxy_manager.py index b8b6a0b..e4db235 100644 --- a/haproxy_manager.py +++ b/haproxy_manager.py @@ -2351,9 +2351,20 @@ def generate_config(): except Exception as e: logger.error(f"Failed to create {suspended_list_path}: {e}") + # Access-log destination for the `log` line in the global section. + # Default 172.18.0.1:514 is the docker bridge gateway for WHP's + # `client-net`, i.e. the host, where rsyslog's imudp listener is bound + # by setup-haproxy-logrotate.sh. Overridable so this image stays usable + # on standalone/home deployments with a different bridge subnet or a + # remote log collector -- set HAPROXY_SYSLOG_TARGET to `:`. + # UDP, so an absent listener drops log lines and never affects request + # handling. + syslog_target = os.environ.get('HAPROXY_SYSLOG_TARGET', '172.18.0.1:514').strip() + # Add Haproxy Default Headers default_headers = template_env.get_template('hap_header.tpl').render( cluster_secret = get_or_create_cluster_secret(), + syslog_target = syslog_target, ) config_parts.append(default_headers) diff --git a/templates/hap_header.tpl b/templates/hap_header.tpl index 35b7773..de59f98 100644 --- a/templates/hap_header.tpl +++ b/templates/hap_header.tpl @@ -2,20 +2,46 @@ # Global settings #--------------------------------------------------------------------- global - # to have these messages end up in /var/log/haproxy.log you will - # need to: + # ACCESS LOG DESTINATION. # - # 1) configure syslog to accept network log events. This is done - # by adding the '-r' option to the SYSLOGD_OPTIONS in - # /etc/sysconfig/syslog + # This used to be `log 127.0.0.1 local2`, which was a silent black hole: + # 127.0.0.1 is the CONTAINER's own loopback, nothing has ever listened on + # udp/514 in the container netns, and there is no /dev/log in the image. + # Every access log line -- ~1.5M/day across the whole edge -- was written + # to a socket with no receiver and dropped. Nothing errored, nothing + # warned, and `haproxy -c` was perfectly happy. The cost only shows up + # during an incident: per-IP 429s, tarpits, wp-admin gate redirects, + # WAF 403s and `silent-drop`s left no record anywhere, so the edge could + # not be asked what it had rejected. Only aggregate stick-table counters + # survived. # - # 2) configure local2 events to go to the /var/log/haproxy.log - # file. A line like the following can be added to - # /etc/sysconfig/syslog + # Now points at the DOCKER BRIDGE GATEWAY, where the host's rsyslog has an + # imudp listener bound (installed idempotently by WHP's + # setup-haproxy-logrotate.sh, which also writes the logrotate stanza). + # The host writes local2 to /var/log/haproxy.log and stops it there, so it + # does not also flood /var/log/messages or the Graylog forwarder. # - # local2.* /var/log/haproxy.log + # WHY NOT `log stdout format raw local0`: it is INCOMPATIBLE with the + # `daemon` keyword below, and incompatible SILENTLY. Verified on the + # pinned 3.0.11 binary: with `daemon` set, a `log stdout` config serves + # traffic normally and emits ZERO log lines, and `haproxy -c` returns 0 + # with no error and no warning -- so the CI config gate + # (scripts/validate-rendered-config.py) cannot catch it either. Making it + # work means dropping `daemon` / adding -db so haproxy stays in the + # foreground, which in turn breaks the three synchronous + # `subprocess.run(['haproxy', '-W', ...], check=True)` launch sites in + # haproxy_manager.py (they would block until the 180s timeout and then be + # killed). That is a change to the exact code path whose failure mode is + # "container Up, ports 80/443 never bound, every site down, /health still + # 200". Not worth it for a logging change. # - log 127.0.0.1 local2 + # UDP means a dead listener degrades to dropped log lines, never to a + # stalled or failing request path -- the correct failure direction for an + # edge fronting ~60 customer sites. + # + # len 2048 accommodates the enriched log-format in hap_listener.tpl + # (URL + User-Agent + UUID); the default 1024 would truncate long ones. + log {{ syslog_target }} len 2048 format rfc5424 local2 info chroot /var/lib/haproxy pidfile /var/run/haproxy.pid @@ -122,7 +148,11 @@ defaults maxconn 3000 # Per-request unique reference, used: - # - in the log line (httplog includes %ID) + # - in the access log line, as the `id=` field of the custom log-format + # in hap_listener.tpl. NOTE: `option httplog` does NOT include %ID + # (verified against haproxy 3.0.11) -- this comment used to claim it + # did, which made the support workflow below look supported when it + # was not. The explicit log-format is what actually carries it. # - echoed to clients in the X-Request-Reference response header on # WAF blocks so a customer can quote it when opening a support ticket # - embedded in /etc/haproxy/errors/403-waf.html so a blocked visitor diff --git a/templates/hap_listener.tpl b/templates/hap_listener.tpl index 3035470..e15a17d 100644 --- a/templates/hap_listener.tpl +++ b/templates/hap_listener.tpl @@ -19,9 +19,44 @@ frontend web # response, including haproxy-generated ones (blocks, default page). http-after-response set-header alt-svc "h3=\":443\"; ma=86400" - # Capture Host header so it appears in httplog output (in %hr field) + # Capture Host header so it appears in httplog output (in %hr field). + # ORDER IS LOAD-BEARING: this is capture slot 0, referenced by the + # access log-format below as %[capture.req.hdr(0)]. http-request capture req.hdr(Host) len 64 + # Capture slot 1 = User-Agent. Incident response needs it to tell a + # scanner from a browser, and it is not in `option httplog` output. + # Any new capture MUST be appended AFTER this line, never inserted + # above it, or the slot indices in the log-format silently shift and + # the access log starts attributing the wrong string to the wrong field. + http-request capture req.hdr(User-Agent) len 200 + + # --- Access logging ----------------------------------------------------- + # Scoped to THIS frontend on purpose: it references capture slots and + # var(txn.real_ip), which only exist here. Putting it in `defaults` would + # apply it to the stats frontend and every backend too, where those + # samples are undefined. + # + # `log-format` overrides `option httplog` for this proxy (haproxy emits a + # harmless warning saying so). The first 16 fields are byte-identical to + # the 3.0 httplog default, so anything that already parses httplog keeps + # working; the `key=value` tail is additive. + # + # Why the default httplog is not enough for incident response: + # %ci is the PROXY's address for Cloudflare-fronted sites, not the + # visitor. The real client is var(txn.real_ip), resolved further + # down from CF-Connecting-IP / X-Real-IP / X-Forwarded-For and only + # honoured from trusted proxies. BOTH are logged: cip= is who to + # rate-limit or block, %ci is which edge it arrived through. + # %ID is NOT included by `option httplog` (verified against + # haproxy 3.0.11). Without it the documented support workflow + # -- X-Request-Reference -> access log -> coraza audit.log -> rule_id + # -- cannot be completed. id= is what makes that join possible. + # host=/ua= identify the vhost and client; %ST/%B/%tsc give status, + # bytes and the termination state that distinguishes a rate-limit + # deny (PR--) from a tarpit (PT--) from a normal close. + log-format "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r cip=%[var(txn.real_ip)] id=%ID host=%[capture.req.hdr(0)] ua=%[capture.req.hdr(1)] sni=%[ssl_fc_sni] hv=%[fc_http_major]" + # --- URI normalisation (MUST be the first path-touching block here) --- # Every path-based control in this frontend (the ACME health-check bypass, # wp-login, xmlrpc, the wp-json/batch virtual patch, the wp-admin gate, the