fix(logging): log PHP requests and the default apache vhost - #60
Merged
zebby76 merged 1 commit intoSep 3, 2026
Merged
Conversation
Two defects that leave the same hole from opposite ends: the requests that matter
most were the ones nobody recorded.
nginx set access_log off inside the PHP location, so a PHP request never reached
the access log. The only trace was php-fpm's own line, which begins "- -": its
%R is the peer address of the connection, and a unix socket has none. No client
address, no Host, no X-Forwarded-For, no request id, and with the FastCGI cache
enabled a HIT never reaches php-fpm at all, so it was recorded nowhere.
apache pointed the default vhost's ErrorLog and CustomLog at /dev/null unless
DEBUG was set. A vhost-level directive replaces the server-level one rather than
adding to it, so the server-level CustomLog /dev/stdout never saw this vhost --
the only one the image ships. Nothing was logged: not the 4xx, not the 5xx, not
the PHP errors mod_proxy_fcgi relays.
Measured on the published images, three requests, counting the lines each
produced:
nginx before nginx after apache before apache after
PHP 1 ("- -") 2 1 ("- -") 2
static 1 1 0 1
404 2 2 0 1
php-fpm's line is kept and its format corrected: %{REMOTE_ADDR}e reads the
client address from the FastCGI parameters, where nginx and apache both put it.
The two lines are not redundant -- nginx carries the HTTP view (Host,
X-Forwarded-For, request id, upstream time, cache status), php-fpm the PHP one
(script path, duration, peak memory, CPU). An operator who wants a single line
sets PHP_FPM_ACCESS_LOG=/dev/null; that knob already exists.
DEBUG keeps its meaning: it raises the daemon log level. It no longer decides
whether the vhost is logged at all.
Both assertions fail against the published images -- on nginx only the PHP one,
on apache both, which is the shape of the two defects.
Contributor
Author
|
Rebased on While resolving it I found something worth flagging: It is one line and it belongs to the file this pull request already touches, so it is restored here rather than in a separate change. After a full run on both variants: 0 leftovers. |
zebby76
force-pushed
the
fix/log-php-requests-and-apache-vhost
branch
from
September 3, 2026 15:33
1030966 to
36ba6b6
Compare
zebby76
added a commit
that referenced
this pull request
Sep 3, 2026
…tore logging (backport of #57, #58, #59, #60 to 8.4) (#61) * fix(nginx): wire the fastcgi buffer settings (#57) NGINX_FASTCGI_BUFFER_SIZE, NGINX_FASTCGI_BUFFERS_COUNT and NGINX_FASTCGI_BUFFERS_SIZE were declared in 40-nginx.sh and documented in the README with defaults of 32k, 8 and 32k -- and appeared in no template. `nginx -T | grep -c fastcgi_buffer` on the published image returns 0. nginx therefore ran its own default, one page, and the response header has to fit in the first buffer. Anything above that fails as "upstream sent too big header while reading response header from upstream", surfaced to the client as a 502. A framework putting a session cookie, a Set-Cookie pair and a few Link headers on the response reaches that on an ordinary request. Measured on smalswebtech/base-php:8.5.9-nginx. The threshold is lower than expected -- this is not a large-header edge case: response header published published, knob=64k this branch knob=64k 4 KB 502 502 200 200 9 KB 502 502 200 200 40 KB 502 502 502 200 The second column is the part worth keeping in mind: raising the documented variable changed nothing, because nothing read it. An operator hitting this had a knob that looked like the fix and was not one. The 40 KB row is correct behaviour: 32k is the configured buffer, and the knob now moves it. The assertion added to tests.web.bats is nginx-only. apache reaches the same wall through mod_proxy_fcgi, which caps a header line at 8k with no equivalent setting, so a 9 KB header answers 500 there before and after. That belongs with the apache module and vhost work, not here. * fix(logrotate): keep directive arguments intact and validate the config at boot (#58) LOGROTATE_DEFAULT_OPTIONS was split on whitespace and then sorted, so a directive carrying an argument arrived as two lines in alphabetical order. logrotate rejects that, skips the whole stanza, and stops rotating every file it matched. Nothing said so: the container started normally, the event listener answered RESULT 4 once a minute into the tick noise, and the volume filled until the pod was evicted. Measured on smalswebtech/base-php:8.5.9-nginx with the documented default plus "maxage 7", writing a 60 MB log and running the script the TICK_60 listener runs: value stanza rotated the default compress copytruncate ... yes the default + "maxage 7" 7 compress copytruncate maxage NO Directives are separated by ';' or a newline now, never by whitespace, so an argument stays with the directive it belongs to. A value containing neither separator keeps the old whitespace split -- exactly the set of values that could ever have worked, argument-less directives only -- so nothing that works today stops working. The sort is gone as well. logrotate reads directives in order and a later one overrides an earlier one, so sorting them changed what the stanza meant. Deduplication stays, order-preserving. And the rendered configuration is checked at startup. logrotate --debug exits 1 on a stanza it cannot parse and writes no state file, which makes it exactly the right check to run before supervisord starts: value published image this branch "compress;7" starts, rotates nothing exits 1, names the file and line Worth knowing for anyone extending this: logrotate accepts an unknown bare word without complaint -- "notadirective" parses and exits 0. Only a structural error is caught, which is what the old splitting produced and what this guards against. * fix(supervisor): treat any exit of a critical program as fatal (#59) The listener keyed on the event payload's `expected` field, on the premise that a deliberate stop carries expected:1 and anything else is a crash. That reads the field as "supervisor asked for this exit". It does not mean that: it means the exit code was in the program's `exitcodes` list, which defaults to 0. So an exit code of 0 was ignored whoever caused it. A SIGTERM reaching the php-fpm master from outside supervisor -- a sidecar, an operator, anything with namespace access -- makes it exit 0, and the container was left running with no php-fpm behind the web server. That is precisely the state this listener exists to end, and it was the one case it let through. For nginx, php-fpm and apache there is no exit code that means "this was fine": they run until the container stops. Any exit is now fatal. Nothing needs filtering out in exchange. Supervisor moves a program it stops itself through STOPPING to STOPPED and emits no PROCESS_STATE_EXITED at all, so a container shutdown and a `supervisorctl stop` never reach this code path. Measured on both images, across the four ways a program can go away: published this branch SIGTERM to the php-fpm master up, php-fpm EXITED container exits SIGKILL to the php-fpm master container exits container exits supervisorctl stop php-fpm up, php-fpm STOPPED up, php-fpm STOPPED docker stop exit 0, no trigger exit 0, no trigger The third row is the documented behaviour from the change that introduced the listener, and the fourth is the risk this change had to rule out: a spurious shutdown on every clean stop. Neither moved. The assertion added to tests.web.bats uses a bounded wait on the container state rather than the retry helper -- retry stops as soon as its command succeeds, and container_running_state succeeds while printing "true", so it returned immediately and asserted nothing. * fix(logging): log PHP requests and the default apache vhost (#60) Two defects that leave the same hole from opposite ends: the requests that matter most were the ones nobody recorded. nginx set access_log off inside the PHP location, so a PHP request never reached the access log. The only trace was php-fpm's own line, which begins "- -": its %R is the peer address of the connection, and a unix socket has none. No client address, no Host, no X-Forwarded-For, no request id, and with the FastCGI cache enabled a HIT never reaches php-fpm at all, so it was recorded nowhere. apache pointed the default vhost's ErrorLog and CustomLog at /dev/null unless DEBUG was set. A vhost-level directive replaces the server-level one rather than adding to it, so the server-level CustomLog /dev/stdout never saw this vhost -- the only one the image ships. Nothing was logged: not the 4xx, not the 5xx, not the PHP errors mod_proxy_fcgi relays. Measured on the published images, three requests, counting the lines each produced: nginx before nginx after apache before apache after PHP 1 ("- -") 2 1 ("- -") 2 static 1 1 0 1 404 2 2 0 1 php-fpm's line is kept and its format corrected: %{REMOTE_ADDR}e reads the client address from the FastCGI parameters, where nginx and apache both put it. The two lines are not redundant -- nginx carries the HTTP view (Host, X-Forwarded-For, request id, upstream time, cache status), php-fpm the PHP one (script path, duration, peak memory, CPU). An operator who wants a single line sets PHP_FPM_ACCESS_LOG=/dev/null; that knob already exists. DEBUG keeps its meaning: it raises the daemon log level. It no longer decides whether the vhost is logged at all. Both assertions fail against the published images -- on nginx only the PHP one, on apache both, which is the shape of the two defects.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Two defects that leave the same hole from opposite ends: the requests that matter most were the
ones nobody recorded.
nginx set
access_log offinside the PHP location, so a PHP request never reached the accesslog. The only trace was php-fpm's own line, which begins
- -: its%Ris the peer address of theconnection, and a unix socket has none. No client address, no
Host, noX-Forwarded-For, norequest id — and with the FastCGI cache enabled a HIT never reaches php-fpm at all, so it was
recorded nowhere.
apache pointed the default vhost's
ErrorLogandCustomLogat/dev/nullunlessDEBUGwasset. A vhost-level directive replaces the server-level one rather than adding to it, so the
server-level
CustomLog /dev/stdoutnever saw this vhost — the only one the image ships. Nothingwas logged: not the 4xx, not the 5xx, not the PHP errors
mod_proxy_fcgirelays.Measured
Three requests against the published images and against this branch, counting the lines each
produced:
- -- -On keeping php-fpm's line
Its format is corrected rather than silenced:
%{REMOTE_ADDR}ereads the client address from theFastCGI parameters, where nginx and apache both put it. Verified:
The two are not redundant — nginx carries the HTTP view (
Host,X-Forwarded-For, request id,upstream time, cache status), php-fpm the PHP one (script path, duration, peak memory, CPU). An
operator who wants a single line sets
PHP_FPM_ACCESS_LOG=/dev/null; that knob already exists.DEBUGkeeps its meaning: it raises the daemon log level. It no longer decides whether the vhostis logged at all.
Verified
Against the published images the two new assertions fail on nginx for the PHP one only, and on
apache for both — the shape of the two defects.