fix(logrotate): sharedscripts, install hex_trim_syslog, and drop redundant delaycompress - #163
Conversation
config_syslogd writes /usr/sbin/hex_trim_syslog into the syslog logrotate postrotate, but nothing ever installed it. The script has been in data/hex_syslogd since the initial commit; its sibling hex_log_event.sh is installed a few lines above and this one was simply missed. Effect on a running node: every nightly rotation logged three 'No such file or directory' errors, and the /var/log/messages size budget the script enforces was never applied. Because it is postrotate guarded by '|| true' the rotation itself still happened, which is why this stayed invisible. Verified on jim-1cc: before, 'logrotate -f /etc/logrotate.d/syslog' logged the missing-file error; after installing, it exits 0 with no error. Traced the script under sh -x with the real limit it is passed (4592725 KB) against a 4 KB total -- the loop does not execute and no retention is removed, so it is inert until /var/log/messages* actually exceeds the budget. Signed-off-by: Jim Lin <jim.lin@bigstack.co> Co-authored-by: Eandalf <clinah@connect.ust.hk> Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
WriteLogRotateConf emitted delaycompress for every generated config. That directive exists for the case where the writing process keeps its old file descriptor and must be signalled to reopen, so the newest rotated generation has to stay uncompressed until the next cycle. Every LogRotateConf in hex and cubecos -- all 30 of them -- sets copytruncate, so the rotated file is already a finished copy that nothing is still writing to. Delaying bought nothing and kept the single largest generation uncompressed. Measured on accept-3cc: logstash.log.1 was 1.4G uncompressed against logstash.log.2.gz at 25M, a ~56x difference on the generation that dominates the footprint. Removing it and re-running logrotate reclaimed 3.0G on cc1, 1.1G on cc2 and 0.8G on cc3 in a single pass, and cleared ceph's 'mon cc2 is low on available space'. Done here rather than per-config in cubecos because extraArgs is written before the common block, so a nodelaycompress override would be overridden again by the directive it is trying to cancel. Signed-off-by: Jim Lin <jim.lin@bigstack.co> Co-authored-by: Eandalf <clinah@connect.ust.hk> Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
WriteLogRotateConf emitted prerotate/postrotate without sharedscripts, so logrotate ran them once per matched file -- its documented behaviour. Every script we generate is a 'signal the service once' operation, so a glob matching N files fired N signals in the same second. For httpd that is up to eleven overlapping 'systemctl reload httpd.service' calls racing each other in the master's worker lifecycle, which can take httpd down outright and 503 Horizon and Keystone on whichever control node holds the VIP (cubecos#1192). The same shape applied to syslog, where three of five files rotate and hex_trim_syslog therefore ran three times per night, and to prometheus's killall -HUP. It also had to be fixed before rotation moves to hourly: eleven reloads a day becomes two hundred and sixty four. Verified on accept-3cc and jim-1cc: forced rotation of the httpd config ran the postrotate script 11 and 9 times respectively before, exactly 1 after. Measured on the live service, a forced rotation produced 4 real httpd reloads before and 1 after, with httpd staying active and Horizon answering 302. Signed-off-by: Jim Lin <jim.lin@bigstack.co> Co-authored-by: Eandalf <clinah@connect.ust.hk> Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
SekiXu
left a comment
There was a problem hiding this comment.
Ran a scoped experiment on a 1cc (logrotate 3.18.0) to check one interaction, and it came out in your favour — recording it here so it's not re-litigated later.
postrotate runs before compression, so what hex_trim_syslog observes is byte-for-byte identical with and without delaycompress — messages + plain messages.1 + .2.gz….4.gz in both. Dropping delaycompress does not shrink the set the script can match.
One cosmetic side effect when the trim actually fires: it removes messages.1 during postrotate, and logrotate then tries to compress the file that just went away —
trim: removing messages.1
error: unable to open /var/log/messages.1 for compression: No such file or directory
Deterministic, 6/6 forced cycles, and absent with delaycompress. No data loss and the trim still does its job, so not a blocker — but it does mean the "No such file or directory" line the install rule removes comes back in a different form on over-budget nights. Cheap to avoid if you want the journal fully clean.
… trim hex_trim_syslog runs from the syslog postrotate, and logrotate runs postrotate *before* compression. Dropping delaycompress in 56fdc47 made messages.1 the generation logrotate compresses in the same cycle, so a trim that reaches .1 removes the file logrotate is about to open: trim: removing messages.1 error: unable to open /var/log/messages.1 for compression: No such file or directory That is the same class of error fea23e1 installed the script to stop -- it would have come back in a different form, on exactly the over-budget nights the trim exists for. Stopping the loop at .2 avoids it, and costs the budget nothing: the next rotation renames .1 to .2, so the same bytes become eligible one cycle later. Reported by SekiXu in review on #163, who measured the interaction and confirmed the set the script can match is byte-for-byte identical with and without delaycompress -- so this is the only thing that needed changing. Verified on jim-1cc (logrotate 3.18.0), in an isolated tree mirroring the real syslog config -- compress, no delaycompress, copytruncate, the trim in postrotate -- forced with a 1KB limit so the loop reaches the newest generation. With the old bound the "removing messages.1" line is followed by the compression error; with the new one gzip runs normally and no error is logged. The installed script stays inert at the real limit: total 179712 KB against LIMIT 4592725. Refs #163 Signed-off-by: Jim Lin <jim.lin@bigstack.co> Co-authored-by: Eandalf <clinah@connect.ust.hk> Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
Thank you for catching that. Fixed in cb13101. |
…ove something hex_trim_syslog has never been able to remove a compressed generation, and since cb13101 it has not been able to remove anything at all. Two mismatches with the directory it runs against, one of them mine: - It tested `-e /var/log/messages.$I` only. WriteLogRotateConf always emits `compress` and the global conf sets no `dateext`, so at postrotate time the directory holds `messages`, a still-uncompressed `messages.1`, and `messages.2.gz` onward. The only unsuffixed generation that ever exists is .1 -- which cb13101 correctly stopped it from touching, leaving a loop with nothing it could match. - `I=14` mirrored the old global `rotate 14`. b5ba5d8 raises that to `retention * 24`, rendering as 336, so even with .gz matching the scan would have covered generations 2..14 of up to 336 -- and a log that reaches 336 generations is exactly the busy log the budget exists for. Take the generation list from the filesystem instead of counting down from a literal. That removes the coupling that has now drifted twice, and it is immune to whatever `rotate` becomes next. messages.1 stays excluded for cb13101's reason: postrotate runs before compression, so .1 is the file logrotate is about to open. Reported by SekiXu in review on #165, who also traced it back to his own #163 measurement -- "the matchable set is byte-for-byte identical with and without delaycompress" was already this fact, one step short of the conclusion. Verified on jim-1cc, both revisions run out of git with only /var/log rewritten to a scratch dir, seeded to the real postrotate shape observed on that node (messages, plain messages.1, messages.2.gz..messages.14.gz) and LIMIT set to a sixth of the total: shipped total 3236 -> 3236 removed nothing fixed total 3236 -> 688 messages.1 survived Inert at the real budget: with the messages set at 168816K against a 5% budget of 4592725K on accept-3cc, a run changes nothing. And seeded to 336 generations with a large one at .300, it trims oldest-first down to .299 -- generations the old bound could never reach. Refs bigstack-oss/cubecos#1433 Signed-off-by: Jim Lin <jim.lin@bigstack.co> Co-authored-by: Eandalf <clinah@connect.ust.hk> Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
What type of PR is this?
What this PR does / why we need it
Three defects in log rotation, all in the generator rather than in any one generated file — which is why they reproduced identically across httpd, syslog and prometheus.
sharedscriptswas never emitted.WriteLogRotateConfwroteprerotate/postrotateblocks without it, so logrotate ran them once per matched file — its documented behaviour. Every script CubeCOS generates is a "signal the service once" operation, so a glob matching N files fired N signals within the same second. For/var/log/httpd/*.logthat is up to eleven overlappingsystemctl reload httpd.servicecalls racing in the master's worker lifecycle, which can crash httpd outright and 503 Horizon and Keystone on whichever control node holds the VIPhex_trim_syslogwas referenced but never installed.config_syslogdwrites/usr/sbin/hex_trim_sysloginto the syslog logrotate postrotate, but no install rule ever shipped it. The script has been indata/hex_syslogdsince the initial commit, and its siblinghex_log_event.shis installed a few lines above — this one was simply missed. Every nightly rotation loggedNo such file or directory, and the/var/log/messagessize budget it enforces never applieddelaycompresswas emitted unconditionally and is redundant here. It exists for the case where the writing process keeps its old file descriptor and must be signalled to reopen, so the newest rotated generation has to stay uncompressed. All 30LogRotateConfdeclarations across hex and cubecos setcopytruncate, so the rotated file is already a finished copy that nothing is still writing to. Delaying only kept the single largest generation uncompressedWhich issue(s) this PR fixes
sharedscriptshalf)Special notes for your reviewer
Why
sharedscriptsis conditional. It is emitted only when a config actually carriesprerotateorpostrotatecommands. On a config with no scripts the directive is meaningless, and three configs is the whole affected set: httpd (systemctl reload httpd.service), syslog (hex_trim_syslog+ rsyslog HUP) and prometheus (killall -HUP prometheus).Why
delaycompressis removed globally rather than per config.extraArgsis written before the common block, so anodelaycompressoverride from cubecos would be cancelled again by the very directive it is trying to override. And since every declaration in both repos setscopytruncate, there is no config that wants the old behaviour.One caveat on
hex_trim_syslog. It has never run in production, so its behaviour on a real oversized/var/log/messagesset is unexercised. It is inert below its limit — traced undersh -xwith the limit it is actually passed (4592725 KB) against a 4 KB total, the loop does not execute — but the trimming path itself only starts being reachable with this PR.Additional documentation