improvement: commit + log + metric on task failure in GC and lifecycle cold-archive#2771
improvement: commit + log + metric on task failure in GC and lifecycle cold-archive#2771delthas wants to merge 1 commit into
Conversation
Hello delthas,My role is to assist you with the merge of this Available options
Available commands
Status report is not available. |
Waiting for approvalThe following approvals are needed before I can proceed with the merge:
|
Codecov Report❌ Patch coverage is
Additional details and impacted files
... and 5 files with indirect coverage changes
@@ Coverage Diff @@
## development/9.5 #2771 +/- ##
===================================================
- Coverage 75.42% 75.31% -0.11%
===================================================
Files 201 201
Lines 13868 13889 +21
===================================================
+ Hits 10460 10461 +1
- Misses 3398 3418 +20
Partials 10 10
Flags with carried forward coverage won't be shown. Click here to find out more. 🚀 New features to boost your workflow:
|
delthas
requested review from
a team,
DarkIsDude,
benzekrimaha and
francoisferrand
| gcFailed.inc({ | ||
| [GC_LABEL_ORIGIN]: process, | ||
| [GC_LABEL_LOCATION]: location, | ||
| [GC_LABEL_RETRYABLE]: retryable === true, |
There was a problem hiding this comment.
is retryable really relevant here?
the metric will only be called if we exhausted the retries anyway, and details will only be in the logs...
| [GC_LABEL_RETRYABLE]: retryable === true, |
There was a problem hiding this comment.
The label distinguishes two operationally distinct failure modes that both land at this metric:
retryable=true— retries genuinely exhausted after ~5 min (backend outage).BackbeatTask.retryonly enters the retry loop whenshouldRetryFunc(err)returns truthy, so this path corresponds to "we tried and gave up."retryable=false— the error was never retryable to begin with, soBackbeatTask.retryshort-circuits on the first attempt (BackbeatTask.js:79-81) without any retry. Common triggers:AccessDeniedafter a role rotation,InvalidRequest/Conflictfrom cloudserver,errors.InternalErrorfrom arsenal when a client cannot be obtained, kafka producer send errors.
Same counter without the label conflates "backend was down for 5 minutes" (expected transient) with "we did not even try because the state was inconsistent" (config/auth problem). The two need different alert thresholds.
There was a problem hiding this comment.
Grounded this by tracing through the actual code + deps. Concrete non-retryable cases in production (each fires the metric with retryable=false on the first attempt, no retry):
-
Cloudserver 5xx / 4xx — cloudserverclient is built on smithy/AWS SDK v3 (
ServiceExceptionat@smithy/smithy-client/dist-es/exceptions.js:1-12). It uses$retryable(with$prefix), not the bareretryablethatBackbeatTask.retryreads.err.retryablestaysundefined. Concrete instances:- 500 internal error, 503 unavailable, 429 throttling — all
$fault: "server"|"client",err.retryable=undefined - 403 AccessDenied (after role rotation, bucket policy tightening)
- 400 InvalidRequest / InvalidArgument
- 409 Conflict (version race on putMetadata between
_getMetadataand_putMetadata)
- 500 internal error, 503 unavailable, 429 throttling — all
-
arsenal.errors.InternalError— arsenalArsenalError(arsenal/lib/errors/index.ts) has noretryablefield. Fires from:_getMetadata:47-51,_batchDeleteData:125-128,_putMetadata:88-92whengetBackbeatMetadataProxy(accountId)returns null (vault-derived client unavailable — vault down, bad account, IAM misconfig)_getMetadata:69-75whenObjectMD.createFromBlob(blob.Body)returnsres.error(corrupted metadata blob)
-
Kafka producer send —
LifecycleColdStatusArchiveTask._deleteColdObject:66-77orphan-cleanup path. node-rdkafka producer errors do not setretryable. -
ECONNREFUSED— the auto-flag inBackbeatTask.js:67-77matches onlyECONNRESET/EPIPE/ETIMEDOUTinerr.code(andTimeoutErrorby name).ECONNREFUSEDis not in the list.
Retryable cases (auto-flagged, retried through the 5 min budget, retryable=true fires only after exhaustion):
- Socket reset mid-flight (
err.code === 'ECONNRESET') — most common - Broken pipe (
EPIPE) - Node socket timeout (
ETIMEDOUT) - Smithy
TimeoutErrorname
Note: err.retryable = true is manually set in only two places in the whole codebase: ReplicateObject.js:544 for source-stream errors and FailedCRRConsumer.js:147. Nothing in GC or lifecycle paths sets it explicitly, so those tasks rely entirely on the auto-flag.
So the bucket split is real and quite skewed: retryable=true = "sustained node-socket flapping", retryable=false = "nearly everything else including HTTP 5xx." Different alert thresholds warranted.
| labelNames: [LIFECYCLE_LABEL_ORIGIN, LIFECYCLE_LABEL_TYPE, | ||
| LIFECYCLE_LABEL_LOCATION, 'retryable'], |
There was a problem hiding this comment.
same, I don't think the "retryable" label is useful
| labelNames: [LIFECYCLE_LABEL_ORIGIN, LIFECYCLE_LABEL_TYPE, | |
| LIFECYCLE_LABEL_LOCATION, 'retryable'], | |
| labelNames: [ | |
| LIFECYCLE_LABEL_ORIGIN, | |
| LIFECYCLE_LABEL_TYPE, | |
| LIFECYCLE_LABEL_LOCATION, | |
| ], |
There was a problem hiding this comment.
The label distinguishes two operationally distinct failure modes that both land at this metric:
retryable=true— retries genuinely exhausted after ~5 min (backend outage).BackbeatTask.retryonly enters the retry loop whenshouldRetryFunc(err)returns truthy, so this path corresponds to "we tried and gave up."retryable=false— the error was never retryable to begin with, soBackbeatTask.retryshort-circuits on the first attempt (BackbeatTask.js:79-81) without any retry. Common triggers:AccessDeniedafter a role rotation,InvalidRequest/Conflictfrom cloudserver,errors.InternalErrorfrom arsenal when a client cannot be obtained, kafka producer send errors.
Same counter without the label conflates "backend was down for 5 minutes" (expected transient) with "we did not even try because the state was inconsistent" (config/auth problem). The two need different alert thresholds.
| }, done); | ||
| }, err => { | ||
| if (err && err.name !== 'ObjNotFound' && err.name !== 'NoSuchBucket') { | ||
| log.error('task failed permanently after retries, committing offset', { |
There was a problem hiding this comment.
is error not logged already (in continuation callback) ?
There was a problem hiding this comment.
There is overlap with BackbeatTask.retry's 'giving up processing as retries ended' (BackbeatTask.js:90), but only for the retryable-exhausted path. The non-retryable path skips the retry loop entirely (shouldRetryFunc(err) === false → doneOnce(...args) at BackbeatTask.js:79-81) and never hits that message — without this new log, non-retryable failures would only leave per-step logs (batchDelete error, putMetadata error) with no task-level "we gave up" signal.
| @@ -310,7 +300,20 @@ class GarbageCollectorTask extends BackbeatTask { | |||
| actionFunc: cb => this._deleteArchivedSourceDataOnce(entry, log, cb), | |||
| shouldRetryFunc: err => err.retryable, | |||
There was a problem hiding this comment.
what is the "retry budget" here?
we need to do something, but should we also increase this budget to ensure we don't just create orphans unexpectedly?
(note: we must increase the retry too much either, i.e. not go beyond Kafka's poll/rebalance deadlines : each task must still be processed within the expected time)
There was a problem hiding this comment.
Current values: BackbeatTask.retry default timeoutS: 300 (5 min), backoff min 1s, max 5 min, factor 1.5, jitter 0.1. gcConfig.consumer.retry can override. On the lifecycle side, retryWrapper is set up from the same shape via the object-processor config.
Ceiling: the sum of retry attempts must stay under max.poll.interval.ms (~5 min default in librdkafka), otherwise a rebalance that catches an in-flight retry hits the BB-777 outer timeout (max.poll.interval - 1s) and forces a pod disconnect. Bumping the retry budget in isolation moves us closer to that boundary; a wider budget would need max.poll.interval widened in step.
There was a problem hiding this comment.
I think 5 min should be widely enough already. It would be pretty rare to have the system failing for 5 minutes but not 10. I'd say no change?
…e cold-archive
Two error paths returned { committable: false } to the consumer after
their retry budget was exhausted, then never called onEntryCommittable.
The offset never advanced past these entries and they stayed in the
OffsetLedger indefinitely. With the BB-777 rebalance-wait-for-drain fix,
this now blocks every rebalance until the outer timeout fires and the
pod restarts, instead of just leaking memory.
Neither flow is retriggered by an upstream cron. The cold-status archive
is a one-shot notification from the cold backend, and LifecycleTask
skips objects with transitionInProgress=true on subsequent scans, so
there is no automatic recovery either way. There is also no dead-letter
mechanism today.
Step 1 is to stop pretending: commit the offset on permanent failure,
log an error message at the point where we drop the entry, and increase
a per-extension counter so operators can alert on it.
- GarbageCollectorTask._deleteArchivedSourceData: move the log + metric
to the outer retry-wrapper's completion callback so it fires once per
final give-up rather than per attempt. Simplify the ObjNotFound /
NoSuchBucket carveout to done(err) (same semantics).
- GarbageCollectorTask._executeDeleteData: same treatment for the hot
transition / restore-expiration paths (already committed on failure
but silently).
- LifecycleObjectTransitionProcessor.processColdStorageStatusEntry:
same idea, in the caller of retryWrapper.retry. Uses
this.getProcessorType() rather than a hard-coded string.
- Add s3_gc_failed_total and s3_lifecycle_failed_total counters with
origin / location / retryable labels (retryable boolean matches the
precedent from OplogPopulatorMetrics.connectorConfigurationApplied).
- Add a "Task permanent failures" TimeSeries panel to the lifecycle
dashboard's Lifecycle Tasks section, plotting both counters by
type/origin + retryable.
- Unit tests: retry tests assert the metric fires with expected args;
three new tests on LifecycleObjectTransitionProcessor cover the
processor's failure metric under retryable=true / retryable=false /
success. Fast retry backoff in the fixtures so they run in ms.
Issue: BB-772
delthas
force-pushed
the
improvement/BB-772/commit-on-poison-pill
branch
from
c7a81fb to
8051dd1
Compare
4 participants
TL;DR — Two task error paths (GC's
_deleteArchivedSourceDataand lifecycle's cold-status archive) currently return{ committable: false }after their retry budget is exhausted, without ever callingonEntryCommittable. The offset never advances past those entries, they linger in theOffsetLedger, and with the BB-777 rebalance-wait-for-drain fix now merged this turns every rebalance that catches one into a forced pod restart. This PR flips those sites to commit on final failure, adds a structured error log at the point of drop, and adds a per-extension counter so operators can alert on the rate.What "final failure" means here
Both sites are wrapped by a
BackbeatTask.retry-style helper with a ~5 minute budget and exponential backoff — they only reach the poison-pill path once retries are exhausted or the error is flagged non-retryable. Realistic triggers include:AccessDeniedafter a role rotation, version conflicts)Why not "kafka will redeliver"
That was the intent behind
committable: false, but it doesn't work: Kafka only redelivers on the next assignment (rebalance / restart), and neither path benefits from an upstream cron. The cold-status message is a one-shot notification from the cold backend; the GCdeleteArchivedSourceDataentry is published exactly once by the archive task in fire-and-forget mode. On top of that,LifecycleTaskexplicitly skips objects withtransitionInProgress=trueon later bucket scans, so the regular pipeline won't pick a stuck object back up either. Effectively the current behavior is "hold the offset forever, ledger grows, and next rebalance forces a pod restart."What this PR does
For each of the two sites:
{ committable: false }— just calldone(err)so the consumer commits the offset like it would for any other completed task.s3_gc_failed_total{origin, location, retryable}for GCs3_lifecycle_failed_total{origin, type, location, retryable}for lifecycleThe log + metric live at the retry-wrapper's completion callback (not inside the task's own error handler) so they fire exactly once per final give-up, not once per attempt.
The
retryablelabel is a boolean, matching the existing precedent fromOplogPopulatorMetrics.connectorConfigurationApplied'ssuccesslabel — prom-client stringifies to"true"/"false".For GC, the pre-existing
ObjNotFound/NoSuchBucketcarveout (return with commit, no retry) is simplified fromdone(err, { committable: true })todone(err)— same semantics, less noise.What this PR does not do
ReplicateObject,MultipleBackendTask,CopyLocationTask,LifecycleUpdateTransitionTask) that usecommittable: falsecorrectly with a producer-callbackonEntryCommittable.Issue: BB-772