chore(supervisor): quieten the startup and tick logging - #62
Merged
zebby76 merged 1 commit intoSep 3, 2026
Merged
Conversation
Five things, all of them noise or duplication rather than behaviour. The TICK_60 subscriber echoed the event header and the payload on every tick, and the listener's stdout was captured as if it were a log stream. It is not: stdout is how an event listener answers supervisor -- READY, RESULT -- so a RESULT line joined the pair. Two lines a minute, forever, in a container whose whole log was 126 lines. Measured over two ticks before and after: tick noise in docker logs 4 lines 0 lines The echo now happens only under DEBUG, where it is still there for anyone debugging a listener, and stdout is no longer captured on either listener. supervisord wrote its log to /app/var/log/supervisord.log as well as to the container output, which nodaemon already gives it. Every line existed twice, and the file sat under two rotators at once: supervisor's own 50 MB x 10 and logrotate, which matches /app/var/log/*.log. The file is gone, along with the Dockerfile line that pre-created it, and the stdout_logfile keys under [supervisord], which are program-section options and were inert there. The logrotate listener ran with autorestart=false, so one crash ended rotation for the life of the container while everything else kept going -- the same silent-failure shape as the configuration bug fixed in Smals-Webtech#58. It matches the fail-fast listener now. And container-entrypoint-cli still reported success as "succesfully"; the other entrypoint lost that typo a while ago. Nothing else moved: rotation still works, both listeners still answer the protocol, supervisor's own output still reaches the container log, and DEBUG=true still prints the events. The assertion added to tests.web.bats reuses the container the suite already has running rather than booting one and sleeping past a tick -- by the time it runs, a TICK_60 has usually fired already, so it waits out the remainder and normally costs nothing.
zebby76
added a commit
that referenced
this pull request
Sep 4, 2026
…ise app-init and fix the docs (backport of #62, #63, #64, #65 to 8.4) (#66) * chore(supervisor): quieten the startup and tick logging (#62) Five things, all of them noise or duplication rather than behaviour. The TICK_60 subscriber echoed the event header and the payload on every tick, and the listener's stdout was captured as if it were a log stream. It is not: stdout is how an event listener answers supervisor -- READY, RESULT -- so a RESULT line joined the pair. Two lines a minute, forever, in a container whose whole log was 126 lines. Measured over two ticks before and after: tick noise in docker logs 4 lines 0 lines The echo now happens only under DEBUG, where it is still there for anyone debugging a listener, and stdout is no longer captured on either listener. supervisord wrote its log to /app/var/log/supervisord.log as well as to the container output, which nodaemon already gives it. Every line existed twice, and the file sat under two rotators at once: supervisor's own 50 MB x 10 and logrotate, which matches /app/var/log/*.log. The file is gone, along with the Dockerfile line that pre-created it, and the stdout_logfile keys under [supervisord], which are program-section options and were inert there. The logrotate listener ran with autorestart=false, so one crash ended rotation for the life of the container while everything else kept going -- the same silent-failure shape as the configuration bug fixed in #58. It matches the fail-fast listener now. And container-entrypoint-cli still reported success as "succesfully"; the other entrypoint lost that typo a while ago. Nothing else moved: rotation still works, both listeners still answer the protocol, supervisor's own output still reaches the container log, and DEBUG=true still prints the events. The assertion added to tests.web.bats reuses the container the suite already has running rather than booting one and sleeping past a tick -- by the time it runs, a TICK_60 has usually fired already, so it waits out the remainder and normally costs nothing. * chore(nginx): correct the default tuning (#63) * chore(nginx): correct the default tuning Seven settings that were inert, disagreed with a neighbouring one, or read the wrong thing. Measured on smalswebtech/base-php:8.5.9-nginx and on an image built from this branch. gzip_types listed application/x-javascript and text/javascript, and mime.types maps .js to application/javascript. No script this image serves was ever compressed: Accept-Encoding: gzip on a 3 KB .js no Content-Encoding Content-Encoding: gzip worker_processes was auto, which counts the cores nginx can see. A cgroup quota is not one of them -- only a cpuset is -- so a 500m limit on a large node still spawned one worker per host core, each carrying its own worker_connections. The count now comes from the container's CPU allowance, rounded up, and stays auto when no limit is set: --cpus=0.5 8 workers -> 1 --cpus=2.5 8 -> 3 --cpus=1 8 workers -> 1 no limit 8 -> 8 (auto, 8 host cores) NGINX_WORKER_PROCESSES overrides it. client_max_body_size was 1m while PHP's upload_max_filesize is 2M, so nginx answered 413 on an upload PHP would have accepted -- two limits disagreeing about the same request. A 1.5 MB body went from 413 to reaching the handler. /healthcheck and /real-time-status used add_header for their Content-Type, which appends to the one nginx has already set: two Content-Type headers on the same response, now one. location ~ \.php$ cannot match /index.php/fr/blog, so a front controller never received PATH_INFO and the fastcgi_split_path_info and PATH_INFO lines under it were dead. apache has always handled this, which left the two variants routing differently: GET /front.php/fr/blog 404 200, path_info=[/fr/blog] Named captures rather than fastcgi_split_path_info, because try_files resets $fastcgi_path_info and that is the usual way this ends up empty. try_files still guards the classic attack: /uploads/photo.jpg/shell.php resolves to a .php that is not on disk, so it stays a 404 rather than photo.jpg being executed. Asserted both ways. limit_req logged a throttled request at error level, dry-run rejections included -- a policy working as intended filling the error log. NGINX_SOFT_THROTTLE_LOG_LEVEL defaults to warn. tcp_nopush only takes effect together with sendfile, which is off by default here, so it was a setting that did nothing. Left as it was, with a comment saying so; changing either without the other is what to avoid. The README also gains the note that both throttling zones key on $remote_addr: behind a router with NGINX_REAL_IP_ENABLED off, that is the router's address, so every visitor shares one bucket and the global 20r/s applies to the whole site. * docs: use the underscore emphasis style the linter expects MD049: super-linter's markdownlint defaults want underscores, and the note added alongside NGINX_WORKER_PROCESSES used asterisks. * fix(app-init): serialise the run-once hooks and document them (#64) * fix(app-init): serialise the run-once hooks and document them The marker in /app/var/lock/appinit records whether the hooks have run, not whether they are running. Replicas sharing the volume it lives on -- an RWX claim is the usual way sessions and uploads are shared -- read it at the same moment, all conclude the hooks are pending, and all run them. A migration hook runs once per replica. Measured with two containers started together, a hook that occupies three seconds, and only /app/var/lock and /app/var/log shared: published 8.5.9 hook ran 2 times this branch hook ran 1 time The lock is held across the check, the run and the write, and the marker is read again inside it, so the second replica finds the work already done and skips. flock releases on process death, so a container that dies mid-init does not wedge the others; APP_INIT_LOCK_TIMEOUT bounds the wait at 300s and a replica that gives up fails its boot rather than run someone else's migration alongside them. The lock is a separate file from the marker: the marker is rewritten, and locking a file while truncating it is how this goes wrong. Note for anyone touching it: the flock in this image is BusyBox's, which takes -s, -x, -u and -n and nothing else. There is no -w, so the bounded wait is a retry around the non-blocking form. The first version of this used --timeout, which BusyBox answers with a usage message and a non-zero exit -- every container then failed its boot with a lock timeout it had never waited for. The hook mechanism was also undocumented -- no mention of /opt/bin/container-entrypoint.d anywhere in the README. It now describes the two kinds of hook and when each runs, and the three things worth knowing before writing one: they run once per /app/var volume rather than once per image, so an ephemeral volume runs them at every start; replicas are serialised; and they see the environment before it is sanitized, secrets included, so a hook that dumps env publishes them. The cli variant runs no late hooks at all. The assertion added to tests.web.bats shares only /app/var/lock and /app/var/log. Sharing /app/var whole is not a realistic deployment and does not work: the two supervisords fight over one RPC socket and the second container exits before it ever reaches its init scripts, which makes the race impossible to observe. * docs: use the term the linter expects textlint terminology: "filenames", not "file names". * docs: correct the drifted documentation, and narrow the rendered credentials (#65) Six statements that did not describe the image, each rechecked against a running container before being rewritten. The README said `PHP_APC_ENABLED=false` disables apcu. The per-extension switch is built from the extension name -- PHP_APCU_ENABLED -- while PHP_APC_ENABLED is the apc.enabled ini directive, a different setting that does not disable anything. Someone following the README turned off nothing and got no warning. docs/php-fpm.md described CONTAINER_HEAP_PERCENT as auto-sizing the memory pools and emitting a warning at startup. Nothing reads it and no warning exists; it has never had an effect. docs/php.md gave opcache.max_accelerated_files as 4000. The image ships 10000 -- opcache is compiled statically here, so the probe reads its real default rather than the fallback the table was written from. The AWS section was the furthest from reality. It described ~/.aws/config and ~/.aws/credentials, which do not exist: the files are /opt/etc/aws/*. And it left unsaid the thing that matters most, that the entrypoint unsets every AWS_* variable it resolved before handing over -- measured, an application process sees none of them, so an SDK in PHP code falls through to instance metadata. Also recorded: AWS_PROFILE changes nothing, only [default] is ever written; and AWS_S3_ENDPOINT_URL is read by nothing, the CLI's own AWS_ENDPOINT_URL_S3 being the variable that works because it carries no default and survives the cleanup. The supervisor table listed SUPERVISOR_XMLRPC_UNIX_SOCKET_CHOWN as a setting. The template line was commented out, so it did nothing; the variable and its row are gone rather than left looking functional. Wiring it is a separate question -- it would let a sidecar with another uid reach the socket, which is a decision, not a documentation fix. And the credentials themselves are now written 0600. They were 0664 in a tree copied with --chmod=777, so the password sat world-readable next to a socket that is 0700. That is defence in depth only: everything in the container runs as uid 1001, php-fpm included, so an application able to run code reaches supervisor whatever the password is. The README says so plainly now instead of implying a boundary that does not exist. Both documentation linters the workflow runs -- markdownlint and textlint -- pass locally against the same super-linter image, which is how MD013, MD028 and a terminology error were caught before pushing rather than after.
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.
Five things, all of them noise or duplication rather than behaviour.
The tick listener
The
TICK_60subscriber echoed the event header and the payload on every tick, and the listener'sstdout was captured as if it were a log stream. It is not — stdout is how an event listener
answers supervisor (
READY,RESULT), so aRESULTline joined the pair.Two lines a minute, forever, in a container whose whole log is 126 lines. Measured over two ticks:
docker logsThe echo now happens only under
DEBUG, where it is still useful, and stdout is no longercaptured on either listener. Verified
DEBUG=truestill prints the events.supervisord's own log
Written to
/app/var/log/supervisord.logand to the container output, whichnodaemonalreadygives it. Every line existed twice, and the file sat under two rotators at once: supervisor's
own 50 MB × 10, and logrotate, which matches
/app/var/log/*.log.Gone — along with the
Dockerfileline that pre-created it, and thestdout_logfile/stderr_logfilekeys under[supervisord], which are program-section options and were inertthere.
The logrotate listener could die quietly
It ran with
autorestart=false, so one crash ended rotation for the life of the container whileeverything else kept going — the same silent-failure shape as the configuration bug fixed in #58.
It matches the fail-fast listener now.
And a typo
container-entrypoint-clistill reported success assuccesfully; the other entrypoint lost thatone a while ago.
Nothing else moved
Rotation still works, both listeners still answer the protocol (
RUNNING), supervisor's own outputstill reaches the container log, and
/app/var/logis empty at boot instead of holding a filenothing writes.
On the assertion
It reuses the container the suite already has running rather than booting one and sleeping past a
tick. By the time it runs a
TICK_60has usually fired already, so it waits out the remainder andnormally costs nothing — the first version added a flat 70 seconds to every job.