fix(logging,network): bound log growth, and let a wedged bond recover itself - #1433
Conversation
39ce503 to
af2259d
Compare
SekiXu
left a comment
There was a problem hiding this comment.
The logrotate half and the hex#163 pairing look right - b34700af is that PR's head, and it is
approved and clean, so a ff merge keeps the SHA.
One gap in the watchdog's arming condition. _network_bond_reachable() already refuses to act
when there is nothing to test against, which is the right instinct, but "gateway exists and
filters ICMP" falls on the other side of that check:
- on a single-node / all-in-one cluster
CUBE_NODE_LIST_IPSholds only this node's own address,
andlocalscorrectly excludes it, so there are no peer targets - the default gateway is then the only target,
targets=1, and if it does not answer ICMP the
function returns 1 permanently network_bond_watchdogruns every 2 min with a 900s holdoff, so a healthy node bounces its
slaves every 15 minutes, indefinitely
Worth noting the tree already took a position on this class of signal: health_link_check is
ping-based and link is NO_REPAIR (core/modules/cli_cluster.cpp:98). Repairing on a
ping-derived signal is the right call here - as your header comment says, it is the only signal
that separates this fault from a healthy bond - so what is missing is just a guard for the case
where the signal cannot be trusted. A persistent "has been reachable at least once" stamp before
arming, or N consecutive failures instead of one, closes it without weakening the real case.
af2259d to
b35492c
Compare
…rked _network_bond_reachable() refuses to act when there is nothing to test against, but "the only target exists and never answers ICMP" falls on the other side of that check and is indistinguishable from a black-holed bond -- permanently. On a single-node cluster CUBE_NODE_LIST_IPS holds only this node's own address, so every peer is correctly excluded as local and the default gateway is the sole target; a gateway that filters ICMP pins the check at unreachable for the life of the node, and network_bond_watchdog then bounces the slaves every holdoff period on a perfectly healthy node, indefinitely. Reproduced on jim-1cc by dropping echo-requests to the gateway alone: both slaves MII up at 1000Mbps, the provider bridge holding 10.1.0.1/16, an ssh session live over the bond -- and network_bond_check returned 1. At the cron interval of 2 min with the 900s holdoff that is a bounce every 15 minutes. Two guards, closing different halves of it: - A persistent marker, $STATE_DIR/network_bond_reachable_seen, created the first time a target actually replies and never removed. The watchdog will not arm without it, which separates the fault this exists for -- was carrying traffic, then stopped -- from "was never measurable". It lives under $STATE_DIR rather than /run because it has to survive a reboot and an A/B upgrade: a node does not become unmeasurable because it restarted. The consequence to be aware of is deliberate: a node that comes up already wedged is left alone, because it is indistinguishable from the filtered-gateway case and there is no evidence a bounce would help. - Three consecutive failing checks instead of one. On a multi-node cluster a lone dropped reply cannot decide anything, since every peer plus the gateway must fail together -- but with a single target, which is exactly the case above, one lost echo was enough to bounce a healthy bond. The counter lives in /run and is cleared by any healthy check. This delays a real repair by about four minutes, against the 14 hours the original fault went unnoticed. The reachable-but-untested path still returns 0 and deliberately does not mark the node as seen: "nothing to test against" is not evidence of health. Reported by SekiXu in review on #1433, who also noted the tree's existing position on this class of signal -- health_link_check is ping-based and link is NO_REPAIR in cli_cluster.cpp. Repairing on a ping-derived signal is still the right call here, since it is the only signal that separated this fault from a healthy bond; what was missing was a guard for when the signal cannot be trusted. Verified on jim-1cc through the real hex_sdk dispatcher, with the bounce stubbed out so no NIC was touched. Gateway ICMP filtered and the marker absent: five runs at BOND_WATCHDOG_FAILS=1 BOND_WATCHDOG_HOLDOFF=0, every other gate wide open, never armed and the failure counter was never even reached. Marker present: failures accumulate 1, 2, 3, and the third arms and runs the repair. A single failing run followed by a healthy one clears the counter. Node left with network_bond_check rc=0 and no leftover firewall rules. Refs #672 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 thank you — this is exactly the right catch, and it goes to the heart of the check. A gateway that refuses to answer pings must not be deemed a network interface failure. Some environments deliberately configure their gateway to reject ping tests, and that is a perfectly normal thing to meet in the field. We discussed this several years ago and I had honestly forgotten it; thanks for picking up this possible case. Your reading of the code is right in every detail. On a single-node / all-in-one cluster Reproduced on [cc1 ~]# # a demonstrably healthy node -- ssh is live over this very bond
MII Status: up (x3) provider holds 10.1.0.1/16
[cc1 ~]# hex_sdk network_bond_check ; echo rc=$?
rc=1Fixed in eee28e0, and I took both of your suggestions rather than choosing between them, because they turn out to close different halves:
One deliberate consequence worth naming: a node that comes up already wedged now has no marker and is left alone. That is the right trade — it is indistinguishable from your rejecting-gateway case, and unlike a node that broke after months of working there is no evidence a bounce would help it. Verified on [cc1 ~]# # gateway rejecting ping, marker absent -- 5 runs at FAILS=1 HOLDOFF=0,
[cc1 ~]# # i.e. every other gate wide open
marker=absent stamp=none fails=none # never armed; the counter was never reached
[cc1 ~]# # marker present -- the real fault
run 1 fails=1 run 2 fails=2 run 3 stamp=written + repair ran
[cc1 ~]# # one failing run, then a healthy one
fails=1 -> clearedYour point about Two things I noticed while testing that this PR does not change, in case you think either should be in scope: On hex#163 — I took your cosmetic finding too, since installing the script was meant to remove "No such file or directory" from the journal and it would have come back in another form on over-budget nights. That landed as hex cb13101 and comes in here via dde45bd. Thanks also for measuring the |
…rked _network_bond_reachable() refuses to act when there is nothing to test against, but "the only target exists and never answers ICMP" falls on the other side of that check and is indistinguishable from a black-holed bond -- permanently. On a single-node cluster CUBE_NODE_LIST_IPS holds only this node's own address, so every peer is correctly excluded as local and the default gateway is the sole target; a gateway that filters ICMP pins the check at unreachable for the life of the node, and network_bond_watchdog then bounces the slaves every holdoff period on a perfectly healthy node, indefinitely. Reproduced on jim-1cc by dropping echo-requests to the gateway alone: both slaves MII up at 1000Mbps, the provider bridge holding 10.1.0.1/16, an ssh session live over the bond -- and network_bond_check returned 1. At the cron interval of 2 min with the 900s holdoff that is a bounce every 15 minutes. Two guards, closing different halves of it: - A persistent marker, $STATE_DIR/network_bond_reachable_seen, created the first time a target actually replies and never removed. The watchdog will not arm without it, which separates the fault this exists for -- was carrying traffic, then stopped -- from "was never measurable". It lives under $STATE_DIR rather than /run because it has to survive a reboot and an A/B upgrade: a node does not become unmeasurable because it restarted. The consequence to be aware of is deliberate: a node that comes up already wedged is left alone, because it is indistinguishable from the filtered-gateway case and there is no evidence a bounce would help. - Three consecutive failing checks instead of one. On a multi-node cluster a lone dropped reply cannot decide anything, since every peer plus the gateway must fail together -- but with a single target, which is exactly the case above, one lost echo was enough to bounce a healthy bond. The counter lives in /run and is cleared by any healthy check. This delays a real repair by about four minutes, against the 14 hours the original fault went unnoticed. The reachable-but-untested path still returns 0 and deliberately does not mark the node as seen: "nothing to test against" is not evidence of health. Reported by SekiXu in review on #1433, who also noted the tree's existing position on this class of signal -- health_link_check is ping-based and link is NO_REPAIR in cli_cluster.cpp. Repairing on a ping-derived signal is still the right call here, since it is the only signal that separated this fault from a healthy bond; what was missing was a guard for when the signal cannot be trusted. Verified on jim-1cc through the real hex_sdk dispatcher, with the bounce stubbed out so no NIC was touched. Gateway ICMP filtered and the marker absent: five runs at BOND_WATCHDOG_FAILS=1 BOND_WATCHDOG_HOLDOFF=0, every other gate wide open, never armed and the failure counter was never even reached. Marker present: failures accumulate 1, 2, 3, and the third arms and runs the repair. A single failing run followed by a healthy one clears the counter. Node left with network_bond_check rc=0 and no leftover firewall rules. Refs #672 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>
dde45bd to
1d3cb91
Compare
…rked _network_bond_reachable() refuses to act when there is nothing to test against, but "the only target exists and never answers ICMP" falls on the other side of that check and is indistinguishable from a black-holed bond -- permanently. On a single-node cluster CUBE_NODE_LIST_IPS holds only this node's own address, so every peer is correctly excluded as local and the default gateway is the sole target; a gateway that filters ICMP pins the check at unreachable for the life of the node, and network_bond_watchdog then bounces the slaves every holdoff period on a perfectly healthy node, indefinitely. Reproduced on jim-1cc by dropping echo-requests to the gateway alone: both slaves MII up at 1000Mbps, the provider bridge holding 10.1.0.1/16, an ssh session live over the bond -- and network_bond_check returned 1. At the cron interval of 2 min with the 900s holdoff that is a bounce every 15 minutes. Two guards, closing different halves of it: - A persistent marker, $STATE_DIR/network_bond_reachable_seen, created the first time a target actually replies and never removed. The watchdog will not arm without it, which separates the fault this exists for -- was carrying traffic, then stopped -- from "was never measurable". It lives under $STATE_DIR rather than /run because it has to survive a reboot and an A/B upgrade: a node does not become unmeasurable because it restarted. The consequence to be aware of is deliberate: a node that comes up already wedged is left alone, because it is indistinguishable from the filtered-gateway case and there is no evidence a bounce would help. - Three consecutive failing checks instead of one. On a multi-node cluster a lone dropped reply cannot decide anything, since every peer plus the gateway must fail together -- but with a single target, which is exactly the case above, one lost echo was enough to bounce a healthy bond. The counter lives in /run and is cleared by any healthy check. This delays a real repair by about four minutes, against the 14 hours the original fault went unnoticed. The reachable-but-untested path still returns 0 and deliberately does not mark the node as seen: "nothing to test against" is not evidence of health. Reported by SekiXu in review on #1433, who also noted the tree's existing position on this class of signal -- health_link_check is ping-based and link is NO_REPAIR in cli_cluster.cpp. Repairing on a ping-derived signal is still the right call here, since it is the only signal that separated this fault from a healthy bond; what was missing was a guard for when the signal cannot be trusted. Verified on jim-1cc through the real hex_sdk dispatcher, with the bounce stubbed out so no NIC was touched. Gateway ICMP filtered and the marker absent: five runs at BOND_WATCHDOG_FAILS=1 BOND_WATCHDOG_HOLDOFF=0, every other gate wide open, never armed and the failure counter was never even reached. Marker present: failures accumulate 1, 2, 3, and the third arms and runs the repair. A single failing run followed by a healthy one clears the counter. Node left with network_bond_check rc=0 and no leftover firewall rules. Refs #672 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>
The single largest log on a control node was not a chatty component, it was one
message repeated. logstash.log.1 on accept-3cc reached 1.4G and 100% of a 200k
line sample was
[INFO ][logstash.outputs.opensearch][log-transformer] Retrying failed action
{status: 429, action: ["index", {...the whole document...}]}
status 429 is OpenSearch rejecting the bulk write. The opensearch output logs one
INFO line per retried document and each line carries the document, so a period of
backpressure does not cost a few hundred lines, it costs gigabytes -- measured at
roughly 60k lines an hour, and the sampled hour ran 00:01 to 01:00 without a gap.
warn rather than off, because the condition itself is still reported: the plugin
logs the connection loss at ERROR ("Attempted to send a bulk request but there
are no living connections in the pool") and the recovery at WARN ("Restored
connection to OpenSearch instance"). What goes away is the per-document retry
line, which is not individually actionable -- the aggregate is what an operator
needs, and 429 backpressure is visible in OpenSearch's own metrics too. Both of
those messages were still present in the live log after the change.
Also raises the Kafka consumer coordinator and its rebalance listener, which log
group join/heartbeat detail at INFO for each of the ten consumer groups the
pipeline runs. That is the majority of what logstash.log holds after a restart --
2080 of 5261 lines on accept-3cc -- though it is small next to the retry spam.
Same shape as the org.apache.http logger upstream already pins to fatal in the
file this appends to.
Appended as a separate file rather than shipping a replacement log4j2.properties,
so a logstash version bump brings upstream's own changes with it and only these
lines are ours; the upstream file is preserved as log4j2.properties.orig beside
it, matching what the recipe already does for logstash.yml. There is no
`loggers =` list in the upstream file, so appended logger keys are picked up --
checked, because that list is the usual reason an appended log4j2 logger is
silently ignored.
Verified on all three accept-3cc nodes. logstash's own logging API is the
authority rather than counting lines, and reports the levels in effect with the
scope intact:
logstash.outputs.opensearch WARN
org.apache.kafka.clients.consumer.internals.ConsumerCoordinator WARN
org.apache.kafka...ConsumerRebalanceListenerInvoker WARN
org.apache.http FATAL (upstream's own)
org.apache.kafka.clients.NetworkClient INFO (left alone)
logstash.outputs.file / http / kafka INFO (left alone)
logstash restarts clean with the file in place, pipelines come up, and there are
no log4j2 configuration errors -- the three apparent hits on a first pass were
INFO lines that merely mention the config path.
Reported by traviswu-bigstack in review on #1433, who asked why a specific log
grows so fast. Worth its own issue rather than this PR: the 429s mean OpenSearch
is refusing writes on that cluster, and it was still flapping its connection
during this work.
Refs #672
Refs #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>
1d3cb91 to
e858eda
Compare
Picks up hex 5cfb997, the other half of the review response on this PR: - fix(logrotate): bound retention by age, so the days promise survives hourly runs -- WriteDefLogRotateConf now emits `maxage <days>` with `rotate` sized so it cannot bind first. Without it, making the timer hourly shrinks the audit window from cubesys.log.default.retention days to that many *hours* for any log that trips the maxsize cap within the hour, which is exactly the busiest ones. - build(rootfs): drop the cron.hourly logrotate move -- dead since logrotate moved to a systemd timer, and the reason the hourly schedule this PR sets was believed to already be in place. Also carries 5740f8e, a dependabot harden-runner bump already on hex develop. Pending as bigstack-oss/hex#165; both repos fast-forward merge, so this SHA stays valid once that lands. Refs #1192 Refs #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>
|
@traviswu-bigstack thank you for the pushback — all three questions were the right ones to ask, and two of them changed the change. Answering each with measurements from "does increasing frequency mean we lost our promise of keeping long enough logs for auditing"Yes, it did, and worse than you put it. But Fixed in bigstack-oss/hex#165, which this PR now depends on: "logrotate causes pressure to cpu & disk"Not measurably, for the part hourly actually adds. A no-op pass over 222 considered logs across 62 configs takes 17–32 ms (three runs). Total compression work is unchanged — the same bytes per day get compressed either way, just spread over more runs instead of one. One real new cost you're right to want named: a log that trips "like why a specific logfile grow so fast"This is the one that changed my understanding, and my first answer was wrong. I sampled the small live log and concluded Kafka consumer chatter. The actual 1.4 GB generation is 100% one message: One INFO line per retried document, each carrying the document — ~60k lines an hour, and the sampled hour ran 00:01→01:00 without a gap. And the 429 is not a logstash problem. From OpenSearch's own log:
OpenSearch refusing writes there is correct behaviour and is not being changed. The defect was the amplification, and that is fixed by raising Also worth noting: there is a system-partition disk-usage alert in kapacitor. The lab nodes simply have no downstream webhook or mail recipient registered, which is why this ran to 0.7% unannounced rather than because nothing watches it. On reverting to dailyThat reinstates the original defect rather than trading it: Housekeeping found on the way
Thanks again — the audit-window question in particular would have shipped as a silent 24x regression on a published tuning. |
SekiXu
left a comment
There was a problem hiding this comment.
The watchdog arming gap is closed, and closed correctly. BOND_REACHABLE_SEEN is written
only on an observed reply and deliberately not on the targets == 0 path, which is the
distinction that matters — "nothing to test against" never becomes evidence of health. The
filtered-gateway single-node case can now never arm, and $STATE_DIR is a safe home for it
(hex/make/hex_support.mk:66 creates it in every rootfs). Taking both suggestions rather
than one was the right call; FAILS=3 covers the neighbour I did not spell out.
One thing left on the bond half.
network_bond_repair bounces every bond, on a node-level signal
_network_bond_reachable pings the gateway and peers over whatever the route table picks,
so its answer is about the node, not about a bond. network_bond_repair then loops every
entry in bonding_masters and bounces each slave in turn.
More than one bond is a supported topology: BondingConfig is a
std::map<std::string, BindIfs> (hex/src/modules/include/policy_network.h:61), the CLI
offers "Select bond interface" with Create/Remove/Update over it
(hex/src/modules/include/cli_network.h:26,30), and firsttime iterates the map to display
them (firsttime_net_bonding.cpp:81).
The bound on this is that the watchdog only ever fires when the management path is already
down, so the node is unreachable regardless. But a separate storage bond can be perfectly
healthy at that moment, and the order of bonding_masters is not defined — so it can be the
one bounced first, 5s down plus 12s up per slave, ~34s off the air before the faulty bond is
even reached. That is new harm on a path that is otherwise still carrying Ceph traffic.
Scoping the repair to the bond that carries the default route would close it, and it is the
only bond the reachability signal actually says anything about. While you are in that file,
core/heavyfs/bond_watchdog.cron still says the watchdog "only pings when an aggregator
already looks wrong" and presents the lost Synchronization bit as the deciding signal — both
describe the design 0cc3a016 replaced.
One question on the timer
logrotate-hourly.conf resets OnCalendar but nothing else. If the packaged
logrotate.timer still carries AccuracySec=1h, the drop-in inherits it and each firing can
be deferred by up to an hour, putting real intervals anywhere in 0-2h. I could not confirm
the packaged unit's contents offline, and the accept-3cc measurements cover a manual run
rather than the schedule — so this may already be answered. If it is not, AccuracySec wants
resetting alongside OnCalendar, for the same reason the comment gives for OnCalendar.
Separately, hex_trim_syslog cannot remove anything as it stands — it never matches .gz,
and I=14 no longer tracks the retention now that rotate is retention * 24. Neither is
this PR's to fix; details on hex#165, which this submodule bump is waiting on anyway.
…rked _network_bond_reachable() refuses to act when there is nothing to test against, but "the only target exists and never answers ICMP" falls on the other side of that check and is indistinguishable from a black-holed bond -- permanently. On a single-node cluster CUBE_NODE_LIST_IPS holds only this node's own address, so every peer is correctly excluded as local and the default gateway is the sole target; a gateway that filters ICMP pins the check at unreachable for the life of the node, and network_bond_watchdog then bounces the slaves every holdoff period on a perfectly healthy node, indefinitely. Reproduced on jim-1cc by dropping echo-requests to the gateway alone: both slaves MII up at 1000Mbps, the provider bridge holding 10.1.0.1/16, an ssh session live over the bond -- and network_bond_check returned 1. At the cron interval of 2 min with the 900s holdoff that is a bounce every 15 minutes. Two guards, closing different halves of it: - A persistent marker, $STATE_DIR/network_bond_reachable_seen, created the first time a target actually replies and never removed. The watchdog will not arm without it, which separates the fault this exists for -- was carrying traffic, then stopped -- from "was never measurable". It lives under $STATE_DIR rather than /run because it has to survive a reboot and an A/B upgrade: a node does not become unmeasurable because it restarted. The consequence to be aware of is deliberate: a node that comes up already wedged is left alone, because it is indistinguishable from the filtered-gateway case and there is no evidence a bounce would help. - Three consecutive failing checks instead of one. On a multi-node cluster a lone dropped reply cannot decide anything, since every peer plus the gateway must fail together -- but with a single target, which is exactly the case above, one lost echo was enough to bounce a healthy bond. The counter lives in /run and is cleared by any healthy check. This delays a real repair by about four minutes, against the 14 hours the original fault went unnoticed. The reachable-but-untested path still returns 0 and deliberately does not mark the node as seen: "nothing to test against" is not evidence of health. Reported by SekiXu in review on #1433, who also noted the tree's existing position on this class of signal -- health_link_check is ping-based and link is NO_REPAIR in cli_cluster.cpp. Repairing on a ping-derived signal is still the right call here, since it is the only signal that separated this fault from a healthy bond; what was missing was a guard for when the signal cannot be trusted. Verified on jim-1cc through the real hex_sdk dispatcher, with the bounce stubbed out so no NIC was touched. Gateway ICMP filtered and the marker absent: five runs at BOND_WATCHDOG_FAILS=1 BOND_WATCHDOG_HOLDOFF=0, every other gate wide open, never armed and the failure counter was never even reached. Marker present: failures accumulate 1, 2, 3, and the third arms and runs the repair. A single failing run followed by a healthy one clears the counter. Node left with network_bond_check rc=0 and no leftover firewall rules. Refs #672 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>
The single largest log on a control node was not a chatty component, it was one
message repeated. logstash.log.1 on accept-3cc reached 1.4G and 100% of a 200k
line sample was
[INFO ][logstash.outputs.opensearch][log-transformer] Retrying failed action
{status: 429, action: ["index", {...the whole document...}]}
status 429 is OpenSearch rejecting the bulk write. The opensearch output logs one
INFO line per retried document and each line carries the document, so a period of
backpressure does not cost a few hundred lines, it costs gigabytes -- measured at
roughly 60k lines an hour, and the sampled hour ran 00:01 to 01:00 without a gap.
warn rather than off, because the condition itself is still reported: the plugin
logs the connection loss at ERROR ("Attempted to send a bulk request but there
are no living connections in the pool") and the recovery at WARN ("Restored
connection to OpenSearch instance"). What goes away is the per-document retry
line, which is not individually actionable -- the aggregate is what an operator
needs, and 429 backpressure is visible in OpenSearch's own metrics too. Both of
those messages were still present in the live log after the change.
Also raises the Kafka consumer coordinator and its rebalance listener, which log
group join/heartbeat detail at INFO for each of the ten consumer groups the
pipeline runs. That is the majority of what logstash.log holds after a restart --
2080 of 5261 lines on accept-3cc -- though it is small next to the retry spam.
Same shape as the org.apache.http logger upstream already pins to fatal in the
file this appends to.
Appended as a separate file rather than shipping a replacement log4j2.properties,
so a logstash version bump brings upstream's own changes with it and only these
lines are ours; the upstream file is preserved as log4j2.properties.orig beside
it, matching what the recipe already does for logstash.yml. There is no
`loggers =` list in the upstream file, so appended logger keys are picked up --
checked, because that list is the usual reason an appended log4j2 logger is
silently ignored.
Verified on all three accept-3cc nodes. logstash's own logging API is the
authority rather than counting lines, and reports the levels in effect with the
scope intact:
logstash.outputs.opensearch WARN
org.apache.kafka.clients.consumer.internals.ConsumerCoordinator WARN
org.apache.kafka...ConsumerRebalanceListenerInvoker WARN
org.apache.http FATAL (upstream's own)
org.apache.kafka.clients.NetworkClient INFO (left alone)
logstash.outputs.file / http / kafka INFO (left alone)
logstash restarts clean with the file in place, pipelines come up, and there are
no log4j2 configuration errors -- the three apparent hits on a first pass were
INFO lines that merely mention the config path.
Reported by traviswu-bigstack in review on #1433, who asked why a specific log
grows so fast. Worth its own issue rather than this PR: the 429s mean OpenSearch
is refusing writes on that cluster, and it was still flapping its connection
during this work.
Refs #672
Refs #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>
Picks up hex 5cfb997, the other half of the review response on this PR: - fix(logrotate): bound retention by age, so the days promise survives hourly runs -- WriteDefLogRotateConf now emits `maxage <days>` with `rotate` sized so it cannot bind first. Without it, making the timer hourly shrinks the audit window from cubesys.log.default.retention days to that many *hours* for any log that trips the maxsize cap within the hour, which is exactly the busiest ones. - build(rootfs): drop the cron.hourly logrotate move -- dead since logrotate moved to a systemd timer, and the reason the hourly schedule this PR sets was believed to already be in place. Also carries 5740f8e, a dependabot harden-runner bump already on hex develop. Pending as bigstack-oss/hex#165; both repos fast-forward merge, so this SHA stays valid once that lands. Refs #1192 Refs #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>
e858eda to
37af585
Compare
…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>
Picks up hex e2a4060, which makes hex_trim_syslog able to remove a generation again. It matched only unsuffixed `messages.$I` while every rotated generation is compressed, and counted down from a literal 14 that no longer tracks the global `rotate` now that it is `retention * 24`. Since cb13101 stopped it touching messages.1 -- correctly, because postrotate runs before compression -- the two together left a loop with nothing it could match at all, so the SYSLOG_DISK_PERC budget had no enforcement behind it. The generation list now comes from the filesystem rather than a counter, which also removes the coupling that has drifted twice. Pending as bigstack-oss/hex#165; both repos fast-forward merge, so this SHA stays valid once that lands. Refs #1192 Refs #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>
…verage The drop-in reset OnCalendar and nothing else, so it inherited AccuracySec=1h from the packaged unit: # /usr/lib/systemd/system/logrotate.timer OnCalendar=daily AccuracySec=1h Persistent=true systemd is then free to defer each firing by up to an hour to batch it with other timers, which puts the real interval anywhere in 0-2h. A two-hour gap is long enough for a busy log to pass 128M and keep going, which is the growth this drop-in exists to bound -- the schedule would have looked hourly in the unit file and not been hourly on the disk. AccuracySec needs no empty reset line, unlike OnCalendar: it is not list-valued, so simply setting it wins. The comment says so, because the empty OnCalendar= immediately above invites copying the wrong pattern. 1m keeps the schedule meaningful while still letting systemd coalesce the timer with others. Reported by SekiXu in review on #1433, who could not confirm the packaged unit's contents offline and flagged it as a question. It was real: the shipped unit does carry AccuracySec=1h, and the drop-in did inherit it. Verified on jim-1cc and accept-3cc -- systemctl show logrotate.timer reported AccuracyUSec=1h before and 1min after, with OnCalendar still the single hourly entry. Refs #1192 Refs #672 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>
_network_bond_reachable pings the default gateway and the cluster peers, all of which leave over the default route, so its answer is about that one path. network_bond_repair then looped every entry in bonding_masters and bounced each slave in turn -- acting on every bond from a signal that describes one of them. Multiple bonds are a supported topology, not a hypothetical: BondingConfig is a map keyed by bond name, the firsttime CLI offers create/remove/update over it, and management, storage and overlay are the obvious split. The order of bonding_masters is not defined, so a healthy storage bond could be bounced first -- 5s down plus 12s up per slave, around 34s off the air before the faulty bond was even reached. That is new harm on a path still carrying Ceph traffic, inflicted because a different path failed. Other bonds are also the ones with no guaranteed ping peer. Nothing promises a storage network answers ICMP, which is the untrustworthy-signal case BOND_REACHABLE_SEEN already exists for; extending the repair to bonds the signal cannot measure would have walked straight back into it. So resolve the bond carrying the management path and act on that alone. The resolution has to know about OVS: in the shipped topology the bond is an OVS port of the `provider` bridge, which holds the management address and the default route, and OVS bridges expose no lower_* links -- the kernel walk finds nothing and has to be paired with ovs-vsctl. The lower_* walk is kept for a Linux bridge or a VLAN stacked over a bond. When nothing resolves the function returns empty and the watchdog does nothing, which is the safe direction for a repair that briefly drops the link. Drops _network_bond_list, which has no callers left. Rewrites bond_watchdog.cron's header, which still described the design 0cc3a01 replaced -- it opened on "a bond whose 802.3ad aggregator has lost synchronization" and presented the lost Synchronization bit as the deciding signal, when that bit was measured *set* on the black-holed node and is logged as a diagnostic that nothing decides on. It now states the real decision, the new scope, and the two guards added since. Both reported by SekiXu in review on #1433. Verified on jim-1cc and accept-3cc through the real hex_sdk dispatcher, with a second bond present and only `ip link set` intercepted so no NIC was touched: bonding_masters aggregatedlinks bond-storage _network_mgmt_bond aggregatedlinks repair would bounce set eth0, set eth1 (aggregatedlinks' slaves) never named dummy-s0, dummy-s1 (bond-storage's slaves) Resolution traced step by step on jim-1cc: default route dev `provider`, not itself a bond, `ovs-vsctl br-exists` rc=0, list-ports yields aggregatedlinks, which has a bonding directory. After removing the test bond, network_bond_check returns 0 on both clusters and the management address is still held. Refs #672 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 thank you — three findings, all three real, and all three now fixed. Taking them in the order you raised them. 1.
|
There was a problem hiding this comment.
if we've identified why a logfile grow so fast, what's the benefit of using hourly rotation. It seems to cause the system jitter with cpu/mem spike, tho it might be small. And the log folder is going to be full with thousands of small log rotation files (14 x 24 x numbers of log files) and make log investiation much harder
|
@traviswu-bigstack understood — the logrotate schedule is back to daily. Reverted in e96331d, with the hex side following in 9287fd0. What came out:
Verified on The cost of reverting, stated plainly: What makes that acceptable now — and what I got wrong when this PR opened — is that your question "why does a specific logfile grow so fast" had a real answer, and it was not "a busy service". The 1.4G generation was 100% one message: the opensearch output logging one INFO line per retried document, with the whole document inline, at roughly 60k lines an hour, while OpenSearch refused writes at its flood-stage watermark. One thing I'd keep on the record rather than close silently: the underlying loop is still there in the shape of the system. Two things from this work that are unaffected by the revert and stay:
Thanks for holding the line on this one — the frequency change would have shipped as a permanent cost for a problem that turned out to have a specific, fixable cause. 🤖 Generated with Claude Code |
Every logrotate config CubeCOS generates sets 'maxsize 128M', but maxsize is only evaluated when logrotate actually runs, and the packaged timer is OnCalendar=daily. A busy log therefore grows unchecked overnight and is rotated exactly once -- the cap never bites. Measured on accept-3cc: logstash.log.1 reached 1.4G under a 128M cap, and /var/log held 8.5G on cc1 and 6.1G on cc2 of an 88G root partition shared with the OS, ceph and both metric stores, with ceph warning 'mon cc2 is low on available space'. The drop-in resets OnCalendar before setting it: drop-ins accumulate list-valued settings, so without the empty reset the timer would fire daily and hourly rather than replacing the schedule. It lives in core/heavyfs next to the DefaultTimeoutStartSec tweaks, since logrotate.timer is a base OS unit rather than a CubeCOS component. Cost is 24 runs a day instead of one; each took ~42s of CPU on a loaded 3-node cluster, nearly all of it compression that has to happen either way. Verified on jim-1cc and accept-3cc: OnCalendar goes from '*-*-* 00:00:00' to '*-*-* *:00:00' as a single entry, and next_elapse moves from tomorrow midnight to the next hour. 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>
Picks up two hex commits that pair with the hourly logrotate timer: - build(syslogd): install hex_trim_syslog, referenced but never shipped. config_syslogd writes it into the syslog postrotate but nothing installed it, so every nightly rotation logged 'No such file or directory' and the /var/log/messages size budget was never applied. - fix(logrotate): drop delaycompress, redundant under copytruncate. All 30 LogRotateConf declarations across hex and cubecos set copytruncate, so the rotated file is already a finished copy and delaying only kept the largest generation uncompressed. Together with the hourly timer, verified on accept-3cc to reclaim 3.0G on cc1, 1.1G on cc2 and 0.8G on cc3 in one pass, clearing ceph's 'mon cc2 is low on available space'. 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>
A control node on accept-3cc sat unreachable for 14 hours with every conventional signal healthy: both slaves UP/LOWER_UP at 1000Mbps, MII Status up, the provider bridge holding the management IP, OVS forwarding with a NORMAL flow and 493M packets counted. One bit was wrong -- the active aggregator's actor port state had lost Synchronization, so no slave was collecting or distributing and ARP failed to every peer including the gateway, in both directions. Recovery was a manual slave bounce over the serial console. Nothing could see it. health_link_check only pings peers, which cannot tell 'the peer is down' from 'my own bond is wedged', and link is NO_REPAIR in s_comps. More fundamentally every repair path in sdk_health.sh is driven from a reachable node over ssh, and a node whose bond has lost sync is by definition not reachable -- so this runs locally from cron, with no dependency on the telemetry or cluster stack, which are exactly what is failing when it is needed. The check is the active aggregator's Synchronization bit (0x08 of the actor port state), not Actor Churn State. Churn reads 'churned' on perfectly healthy nodes here, because the peer never answers LACPDUs and the bond runs permanently defaulted -- identical on all three nodes while two served traffic and one black-holed. Non-802.3ad bonds and nodes with no bond report healthy. network_bond_check is both the watchdog's decision and the operator command, so the two cannot drift. Guards: it acts only when a bond is desynchronized AND the node can reach neither its gateway nor any peer, bounces one slave at a time stopping as soon as sync returns, and holds off 900s between repairs so a fault it cannot fix does not become a flap. ETH00003W is emitted on the fault and ETH00004I on recovery -- ETH rather than NET because ETH is the host NIC category, and directly rather than through logstash's log-to-event-key mapping because the log pipeline is unreachable in this failure. Verified: parser unit-tested against the real broken cc1 aggregator state (active agg port state 71, no Sync -> NOT synced), a healthy one (79 -> synced), and a non-LACP bond (skipped). On jim-1cc and all three accept-3cc nodes network_bond_check reports synced, the watchdog returns 0 without touching any link, and no holdoff stamp is written. event.yaml parses with 52 unique ids and both new events emit to syslog at the right severity. 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>
The committed check reported a false healthy. Proven on jim-1cc: with the active aggregator on the wrong member, the node could not reach its default gateway or any peer, while network_bond_check returned 0 and reported 'synced' -- the aggregator's Synchronization bit was set (ps=79). network_bond_watchdog returns early on a passing check, so cron ran every two minutes against a dead node and never fired. Two LACP state variables were tried as the signal and both give false healthies. Actor Churn State reads 'churned' on perfectly healthy nodes, because a bond whose partner never answers LACPDUs runs permanently defaulted. The Sync bit of the active aggregator reads set on a black-holed node, because which aggregator is active matters more than whether it synchronized. Reachability is the only signal that tracked the fault in every observation, so it is now the decision; the aggregator details are logged as diagnostics and nothing decides on them. Both rejected candidates are recorded in the code so they are not re-derived. Also fixes the reachability probe itself, which pinged this node's own address. CUBE_NODE_LIST_IPS holds the local IP on a single-node cluster and the hostname -i exclusion did not cover every configured address, so the ping succeeded through the loopback path and reported a black-holed node as reachable. Every configured IPv4 address is now excluded. A node with no reachable target at all is reported healthy rather than flapped, and a bond with no live slave is left alone -- that is a link fault a bounce cannot fix. network_bond_check reports through log_* rather than stdout: the caller that matters is cron, which discards both streams, so an echo was thrown away exactly when the diagnostic was worth having. Healthy is log_debug to keep a two-minute check on every node off the log volume; unreachable is log_error and carries the aggregator detail inline. ETH00003W/ETH00004I messages are reworded to match, since they no longer describe synchronization. Verified end to end on jim-1cc with cron driving it unattended: fault induced at 16:02, detected by the 16:12 run, ETH00003W logged, slaves bounced, node reachable again after the second slave, ETH00004I logged -- 38s from CMD to CMDEND, no human involved. Node and cluster healthy afterwards. Landed and re-verified on all three accept-3cc nodes: rc=0, empty stdout, log_error confirmed reaching syslog. 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>
Picks up 'fix(logrotate): run rotation scripts once per cycle, not once per file' -- WriteLogRotateConf now emits sharedscripts for any config that carries prerotate or postrotate commands. Fixes cubecos#1192: /etc/logrotate.d/httpd matches 13 files, so its postrotate ran up to eleven times per rotation, firing eleven overlapping 'systemctl reload httpd.service' calls that race in the master's worker lifecycle and can crash httpd, 503ing Horizon and Keystone on the VIP-owning node. Also fixes the same defect in the syslog config (three hex_trim_syslog runs per night) and prometheus's killall -HUP. Needed before the hourly logrotate timer in this branch takes effect: eleven reloads a day would otherwise become two hundred and sixty four. 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>
…rked _network_bond_reachable() refuses to act when there is nothing to test against, but "the only target exists and never answers ICMP" falls on the other side of that check and is indistinguishable from a black-holed bond -- permanently. On a single-node cluster CUBE_NODE_LIST_IPS holds only this node's own address, so every peer is correctly excluded as local and the default gateway is the sole target; a gateway that filters ICMP pins the check at unreachable for the life of the node, and network_bond_watchdog then bounces the slaves every holdoff period on a perfectly healthy node, indefinitely. Reproduced on jim-1cc by dropping echo-requests to the gateway alone: both slaves MII up at 1000Mbps, the provider bridge holding 10.1.0.1/16, an ssh session live over the bond -- and network_bond_check returned 1. At the cron interval of 2 min with the 900s holdoff that is a bounce every 15 minutes. Two guards, closing different halves of it: - A persistent marker, $STATE_DIR/network_bond_reachable_seen, created the first time a target actually replies and never removed. The watchdog will not arm without it, which separates the fault this exists for -- was carrying traffic, then stopped -- from "was never measurable". It lives under $STATE_DIR rather than /run because it has to survive a reboot and an A/B upgrade: a node does not become unmeasurable because it restarted. The consequence to be aware of is deliberate: a node that comes up already wedged is left alone, because it is indistinguishable from the filtered-gateway case and there is no evidence a bounce would help. - Three consecutive failing checks instead of one. On a multi-node cluster a lone dropped reply cannot decide anything, since every peer plus the gateway must fail together -- but with a single target, which is exactly the case above, one lost echo was enough to bounce a healthy bond. The counter lives in /run and is cleared by any healthy check. This delays a real repair by about four minutes, against the 14 hours the original fault went unnoticed. The reachable-but-untested path still returns 0 and deliberately does not mark the node as seen: "nothing to test against" is not evidence of health. Reported by SekiXu in review on #1433, who also noted the tree's existing position on this class of signal -- health_link_check is ping-based and link is NO_REPAIR in cli_cluster.cpp. Repairing on a ping-derived signal is still the right call here, since it is the only signal that separated this fault from a healthy bond; what was missing was a guard for when the signal cannot be trusted. Verified on jim-1cc through the real hex_sdk dispatcher, with the bounce stubbed out so no NIC was touched. Gateway ICMP filtered and the marker absent: five runs at BOND_WATCHDOG_FAILS=1 BOND_WATCHDOG_HOLDOFF=0, every other gate wide open, never armed and the failure counter was never even reached. Marker present: failures accumulate 1, 2, 3, and the third arms and runs the repair. A single failing run followed by a healthy one clears the counter. Node left with network_bond_check rc=0 and no leftover firewall rules. Refs #672 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>
Picks up hex cb13101, which stops hex_trim_syslog from removing messages.1 -- the generation logrotate compresses in the same cycle, now that delaycompress is gone. Without it an over-budget rotation logs "unable to open /var/log/messages.1 for compression: No such file or directory", the same class of error installing the script was meant to remove. Already merged to hex develop, so the SHA is stable. Refs #1192 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>
The single largest log on a control node was not a chatty component, it was one
message repeated. logstash.log.1 on accept-3cc reached 1.4G and 100% of a 200k
line sample was
[INFO ][logstash.outputs.opensearch][log-transformer] Retrying failed action
{status: 429, action: ["index", {...the whole document...}]}
status 429 is OpenSearch rejecting the bulk write. The opensearch output logs one
INFO line per retried document and each line carries the document, so a period of
backpressure does not cost a few hundred lines, it costs gigabytes -- measured at
roughly 60k lines an hour, and the sampled hour ran 00:01 to 01:00 without a gap.
warn rather than off, because the condition itself is still reported: the plugin
logs the connection loss at ERROR ("Attempted to send a bulk request but there
are no living connections in the pool") and the recovery at WARN ("Restored
connection to OpenSearch instance"). What goes away is the per-document retry
line, which is not individually actionable -- the aggregate is what an operator
needs, and 429 backpressure is visible in OpenSearch's own metrics too. Both of
those messages were still present in the live log after the change.
Also raises the Kafka consumer coordinator and its rebalance listener, which log
group join/heartbeat detail at INFO for each of the ten consumer groups the
pipeline runs. That is the majority of what logstash.log holds after a restart --
2080 of 5261 lines on accept-3cc -- though it is small next to the retry spam.
Same shape as the org.apache.http logger upstream already pins to fatal in the
file this appends to.
Appended as a separate file rather than shipping a replacement log4j2.properties,
so a logstash version bump brings upstream's own changes with it and only these
lines are ours; the upstream file is preserved as log4j2.properties.orig beside
it, matching what the recipe already does for logstash.yml. There is no
`loggers =` list in the upstream file, so appended logger keys are picked up --
checked, because that list is the usual reason an appended log4j2 logger is
silently ignored.
Verified on all three accept-3cc nodes. logstash's own logging API is the
authority rather than counting lines, and reports the levels in effect with the
scope intact:
logstash.outputs.opensearch WARN
org.apache.kafka.clients.consumer.internals.ConsumerCoordinator WARN
org.apache.kafka...ConsumerRebalanceListenerInvoker WARN
org.apache.http FATAL (upstream's own)
org.apache.kafka.clients.NetworkClient INFO (left alone)
logstash.outputs.file / http / kafka INFO (left alone)
logstash restarts clean with the file in place, pipelines come up, and there are
no log4j2 configuration errors -- the three apparent hits on a first pass were
INFO lines that merely mention the config path.
Reported by traviswu-bigstack in review on #1433, who asked why a specific log
grows so fast. Worth its own issue rather than this PR: the 429s mean OpenSearch
is refusing writes on that cluster, and it was still flapping its connection
during this work.
Refs #672
Refs #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>
Picks up hex 5cfb997, the other half of the review response on this PR: - fix(logrotate): bound retention by age, so the days promise survives hourly runs -- WriteDefLogRotateConf now emits `maxage <days>` with `rotate` sized so it cannot bind first. Without it, making the timer hourly shrinks the audit window from cubesys.log.default.retention days to that many *hours* for any log that trips the maxsize cap within the hour, which is exactly the busiest ones. - build(rootfs): drop the cron.hourly logrotate move -- dead since logrotate moved to a systemd timer, and the reason the hourly schedule this PR sets was believed to already be in place. Also carries 5740f8e, a dependabot harden-runner bump already on hex develop. Pending as bigstack-oss/hex#165; both repos fast-forward merge, so this SHA stays valid once that lands. Refs #1192 Refs #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>
Picks up hex e2a4060, which makes hex_trim_syslog able to remove a generation again. It matched only unsuffixed `messages.$I` while every rotated generation is compressed, and counted down from a literal 14 that no longer tracks the global `rotate` now that it is `retention * 24`. Since cb13101 stopped it touching messages.1 -- correctly, because postrotate runs before compression -- the two together left a loop with nothing it could match at all, so the SYSLOG_DISK_PERC budget had no enforcement behind it. The generation list now comes from the filesystem rather than a counter, which also removes the coupling that has drifted twice. Pending as bigstack-oss/hex#165; both repos fast-forward merge, so this SHA stays valid once that lands. Refs #1192 Refs #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>
…verage The drop-in reset OnCalendar and nothing else, so it inherited AccuracySec=1h from the packaged unit: # /usr/lib/systemd/system/logrotate.timer OnCalendar=daily AccuracySec=1h Persistent=true systemd is then free to defer each firing by up to an hour to batch it with other timers, which puts the real interval anywhere in 0-2h. A two-hour gap is long enough for a busy log to pass 128M and keep going, which is the growth this drop-in exists to bound -- the schedule would have looked hourly in the unit file and not been hourly on the disk. AccuracySec needs no empty reset line, unlike OnCalendar: it is not list-valued, so simply setting it wins. The comment says so, because the empty OnCalendar= immediately above invites copying the wrong pattern. 1m keeps the schedule meaningful while still letting systemd coalesce the timer with others. Reported by SekiXu in review on #1433, who could not confirm the packaged unit's contents offline and flagged it as a question. It was real: the shipped unit does carry AccuracySec=1h, and the drop-in did inherit it. Verified on jim-1cc and accept-3cc -- systemctl show logrotate.timer reported AccuracyUSec=1h before and 1min after, with OnCalendar still the single hourly entry. Refs #1192 Refs #672 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>
_network_bond_reachable pings the default gateway and the cluster peers, all of which leave over the default route, so its answer is about that one path. network_bond_repair then looped every entry in bonding_masters and bounced each slave in turn -- acting on every bond from a signal that describes one of them. Multiple bonds are a supported topology, not a hypothetical: BondingConfig is a map keyed by bond name, the firsttime CLI offers create/remove/update over it, and management, storage and overlay are the obvious split. The order of bonding_masters is not defined, so a healthy storage bond could be bounced first -- 5s down plus 12s up per slave, around 34s off the air before the faulty bond was even reached. That is new harm on a path still carrying Ceph traffic, inflicted because a different path failed. Other bonds are also the ones with no guaranteed ping peer. Nothing promises a storage network answers ICMP, which is the untrustworthy-signal case BOND_REACHABLE_SEEN already exists for; extending the repair to bonds the signal cannot measure would have walked straight back into it. So resolve the bond carrying the management path and act on that alone. The resolution has to know about OVS: in the shipped topology the bond is an OVS port of the `provider` bridge, which holds the management address and the default route, and OVS bridges expose no lower_* links -- the kernel walk finds nothing and has to be paired with ovs-vsctl. The lower_* walk is kept for a Linux bridge or a VLAN stacked over a bond. When nothing resolves the function returns empty and the watchdog does nothing, which is the safe direction for a repair that briefly drops the link. Drops _network_bond_list, which has no callers left. Rewrites bond_watchdog.cron's header, which still described the design 0cc3a01 replaced -- it opened on "a bond whose 802.3ad aggregator has lost synchronization" and presented the lost Synchronization bit as the deciding signal, when that bit was measured *set* on the black-holed node and is logged as a diagnostic that nothing decides on. It now states the real decision, the new scope, and the two guards added since. Both reported by SekiXu in review on #1433. Verified on jim-1cc and accept-3cc through the real hex_sdk dispatcher, with a second bond present and only `ip link set` intercepted so no NIC was touched: bonding_masters aggregatedlinks bond-storage _network_mgmt_bond aggregatedlinks repair would bounce set eth0, set eth1 (aggregatedlinks' slaves) never named dummy-s0, dummy-s1 (bond-storage's slaves) Resolution traced step by step on jim-1cc: default route dev `provider`, not itself a bond, `ovs-vsctl br-exists` rc=0, list-ports yields aggregatedlinks, which has a bonding directory. After removing the test bond, network_bond_check returns 0 on both clusters and the management address is still held. Refs #672 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>
Product decision: the log rotation schedule stays daily. Reverts the logrotate.timer drop-in and its install rule, so the packaged OnCalendar=daily stands on its own again -- and with it the AccuracySec=1m pin, which only existed because the drop-in inherited AccuracySec=1h from that same packaged unit. What this gives back has to be said plainly: `maxsize 128M` is evaluated only when logrotate runs, so on a daily timer it is once again a cap that bounds nothing between runs. 41 of the 62 generated configs carry it. A log that grows past 128M during the day is still rotated exactly once, at whatever size it reached -- which is how logstash.log.1 reached 1.4G under that cap. The reason that is acceptable now, and was not when this PR opened, is that the growth had a cause and the cause is fixed. The 1.4G was not a busy service; it was the opensearch output logging one INFO line per retried document, with the whole document inline, while OpenSearch refused writes at its flood-stage watermark -- roughly 60k lines an hour, and 100% of a 200k line sample of that generation. 7dde749 pins that logger to warn, so the amplifier is gone regardless of how often logrotate runs. Raising the frequency treated the symptom; the symptom no longer has a source. The retention work in hex stays, and is not affected by the schedule: maxage carries the days promise at any rotation frequency, which is what cubesys.log.default.retention advertises. Verified on jim-1cc and all three accept-3cc nodes. With the drop-in removed and daemon-reload run, `systemctl cat logrotate.timer` shows only the packaged unit -- OnCalendar=daily, AccuracySec=1h, Persistent=true -- the effective AccuracyUSec returns to 1h, next elapse moves to 00:00:00, the timer stays active, and a real logrotate pass over 188-223 considered logs exits 0 with no output. Refs #1192 Refs #672 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>
Picks up hex 1d8bd9b, the hex-side follow-through on reverting this PR's logrotate timer to daily. `rotate` goes back to the retention value. It had been raised to retention * 24 to cover the worst case an hourly timer allowed, which on the daily schedule means 336 generations for a log that can produce at most 14 -- a number describing a schedule this PR no longer ships. The comment went with it: it had justified `maxage` entirely by the hourly timer, and claimed `rotate` was sized so it could not bind first, which stops being true once `rotate` is the day count again. `maxage` stays, and the commit records why it is not redundant at the same value: on a daily schedule the two agree exactly, but only `maxage` bounds a log that rotates *rarely* -- with notifempty and a quiet service, generations sit for months while staying well inside a count of 14. Pending as bigstack-oss/hex#165; both repos fast-forward merge, so this SHA stays valid once that lands. Refs #1192 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>
9287fd0 to
25bbceb
Compare
What type of PR is this?
What this PR does / why we need it
Two unrelated-looking outages on
accept-3ccturned out to be one theme: the system could not see what was wrong, and in one case its own recovery machinery was the cause.logstash.log.1reached 1.4G under amaxsize 128Mcap,/var/logheld 8.5G on cc1 and 6.1G on cc2 of an 88G root shared with the OS, ceph and both metric stores, and ceph was warningmon cc2 is low on available space. The growth was not a busy service: 100% of a 200k-line sample of that generation was the opensearch output logging one INFO line per retried document, with the whole document inline, at ~60k lines an hour, while OpenSearch refused writes at its flood-stage watermark. That logger is now pinned towarn, which removes the amplifier itself. An earlier revision also moved the logrotate timer to hourly so themaxsizecap would be evaluated more than once a day; that has been reverted on the product owner's call and the schedule stays daily — see the note belowUP/LOWER_UPat 1000Mbps,MII Status: up, the provider bridge holding the management IP, OVS forwarding with a NORMAL flow and 493M packets counted.health_link_checkonly pings peers, which cannot tell "the peer is down" from "my own bond is wedged", andlinkisNO_REPAIR. More fundamentally, every repair path insdk_health.shis driven from a reachable node over ssh — so a node in this state can only be fixed by itself. A cron watchdog now does that, locally, with no dependency on the telemetry or cluster stacksharedscriptsin the logrotate generator ([Bug]: httpd logrotate config missing sharedscripts crash-loops httpd, blocking Horizon on the VIP-owning node #1192),hex_trim_syslogfinally installed, and the redundantdelaycompressdropped — plus, from review,hex_trim_syslogno longer removing the generation logrotate is about to compress,hex_trim_syslogmatching the compressed generations that actually exist so theSYSLOG_DISK_PERCbudget has enforcement behind it at all, and retention bounded bymaxageso the promise is expressed in the days the tuning advertisesWhich issue(s) this PR fixes
Special notes for your reviewer
Why the bond watchdog decides on reachability and not on any LACP state variable. Two candidates were tried and both produce false healthies, which is worth recording so they are not re-derived.
Actor Churn Statereadschurnedon perfectly healthy nodes, because a bond whose partner never answers LACPDUs runs permanently defaulted — identical on all three nodes while two served traffic and one black-holed. The Synchronization bit of the active aggregator reads set on a node that could not reach its own default gateway, because which aggregator is active matters more than whether it synchronized. Reachability is the only signal that tracked the fault in every observation. The aggregator details are logged as diagnostics; nothing decides on them.Why cron and not the health SDK.
cluster_check_repair,_essential_check_oneandlive_migration_gateare all driven from a reachable node. A node whose bond has stopped carrying traffic is by definition not reachable, so none of them can ever get to it. Cron rather than a telegraf exec input for the same reason — the telemetry stack's outputs are all failing precisely when this is needed.Guards on the watchdog. It acts only when the node can reach neither its default gateway nor any peer; it excludes every locally-configured address from that test, because pinging your own IP succeeds through loopback even when the bond carries nothing; it leaves a bond with no live slave alone, since that is a link fault a bounce cannot fix; it will not arm until the node has been observed reachable at least once; it requires three consecutive failing checks rather than one; and it holds off 900s between repairs so a fault it cannot fix does not become a flap.
Why the watchdog needs proof that the signal ever worked. The last two of those guards came out of review, and they close a real hole.
_network_bond_reachable()already declines to act when there is nothing to test against — but "the only target exists and refuses to answer ICMP" falls on the other side of that check, and is then indistinguishable from a black-holed bond, permanently. A gateway configured to reject ping is a normal thing to meet in the field, and must never be read as an interface failure. On a single-node cluster it is also the only target there is:CUBE_NODE_LIST_IPSholds just this node's own address, every peer is correctly excluded as local, and the check is pinned at unreachable for the life of the node — so a healthy node bounced its slaves every 15 minutes, indefinitely.So the watchdog now requires a persistent marker,
$STATE_DIR/network_bond_reachable_seen, written the first time a target actually replies. That separates the fault this exists for — was carrying traffic, then stopped — from "was never measurable". It lives under$STATE_DIRrather than/runbecause it has to survive a reboot and the A/B switch: a node does not become unmeasurable because it restarted. One consequence is deliberate: a node that comes up already wedged is left alone, because it is indistinguishable from the rejecting-gateway case and there is no evidence a bounce would help it. The three-consecutive-failures gate covers the neighbouring case — with a single target, one lost echo reply was otherwise enough to bounce a healthy bond. It delays a real repair by about four minutes, against the 14 hours the original fault went unnoticed.The rotation schedule stays daily. An earlier revision of this PR shipped a
logrotate.timerdrop-in moving evaluation to hourly, so themaxsize 128Mcap in 41 of the 62 generated configs would be checked more than once a day. @traviswu-bigstack pushed back on the cost and the retention implications, and that is reverted — the packagedOnCalendar=dailystands on its own again, and theAccuracySec=1mpin goes with it, since it only existed because the drop-in inheritedAccuracySec=1hfrom that same packaged unit.The consequence is worth stating rather than glossing:
maxsizeis evaluated only when logrotate runs, so on a daily timer it is once again a cap that bounds nothing between runs. What makes that acceptable now, and did not when this PR opened, is that the growth had a cause and the cause is fixed — the 1.4G generation was the opensearch retry amplification, not a busy service, and7dde7496removes it regardless of how often logrotate runs. Raising the frequency treated the symptom; the symptom no longer has a source.maxagein hex#165 is unaffected by the schedule and stays: it states the retention promise in days, which is the unit the tuning is written in, and it is the only bound that says anything about a log that rotates rarely — withnotifemptyand a quiet service, generations can sit for months while staying well inside a count of 14.Additional documentation
Verified on
accept-3cc(3-node HA) andjim-1ccunless stated otherwise.For the requirement "the rotation schedule is the packaged daily one" — the drop-in removed and
daemon-reloadrun, onjim-1ccand all threeaccept-3ccnodes:The timer stays active and a real
logrotatepass over 188–223 considered logs exits 0 with no output on every node.Applying the hex fixes reclaimed disk in one pass and cleared the ceph warning:
Separately, 122 orphaned
*.backupfiles holding 5.04 GiB were found on cc1 alone — logrotate's own collision artifacts, which match no glob in any config, so no retention policy would ever have reclaimed them. Removed across all four nodes, 14.3 GiB total.For the requirement "a wedged bond recovers itself" — induced on
jim-1cc, then left entirely to cron:04:12:01 CROND CMD network_bond_watchdog 04:12:04 ETH00003W bond_not_carrying_traffic 04:12:04 error: network_bond_repair: aggregatedlinks is not carrying traffic [active_agg=2 eth0(agg=1,mii=up,ps=71) eth1(agg=2,mii=up,ps=79)], bouncing [eth0 eth1] 04:12:39 info: network_bond_repair: aggregatedlinks reachable again after bouncing eth1 [active_agg=1 eth0(agg=1,mii=up,ps=79) eth1(agg=2,mii=up,ps=71)] 04:12:39 ETH00004I bond_recovered 04:12:39 CROND CMDEND38 seconds, no human involved. Note the diagnostic at fault time:
ps=79— the Synchronization bit was set while the node was black-holed, which is why the check does not use it.For the requirement "a healthy node behind a gateway that rejects ping is never touched" — the review guards, on
jim-1ccthrough the realhex_sdkdispatcher with the bounce stubbed out, so no NIC was ever touched:Before these guards that same healthy node armed on the first failure, with the 900s holdoff as the only thing limiting the rate — a bounce every 15 minutes forever.
The no-op path, on all four nodes:
For the requirement "one service reload per rotation" (#1192),
For the requirement "
delaycompressremoval does not break compression" — isolated,rotate 14,copytruncate:No errors either way; the newest generation is compressed instead of held. Compression errors seen on the test nodes were environmental — something outside CubeCOS had renamed rotated files to
*.1-<stamp>.backup.For the requirement "
hex_trim_syslogis inert until it is needed",