Repository navigation
RFC: Per-record Logger keys and correlation id in Batch processing #5832
dreamorosi
started this conversation in
RFCs (Request for Comments)
Replies: 0 comments
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Uh oh!
There was an error while loading. Please reload this page.
Uh oh!
There was an error while loading. Please reload this page.
Is this related to an existing feature request or issue?
No. This came out of a design session for a closed source use case. The closest prior work is #5554, which introduced
InvocationScopedin commons.Which area does this RFC relate to?
Batch
Summary
Batch processes records in parallel by default. Logger's temporary keys live in invocation-wide state, so when a record handler calls
logger.appendKeys()orlogger.setCorrelationId(), every other record running at the same time sees those keys. The only fixes available today are to process records one at a time, or to thread a child logger through every function the handler calls.We propose a
recordScopeoption on the Batch processors. When it's on, each record gets its own copy of the Logger temporary keys, starting from the keys the invocation already has. The record handler and any module it imports keep using the ordinary module-levellogger. A companioncorrelationIdoption sets a correlation id per record, from a JMESPath expression or a function. Both options are opt-in. WhetherrecordScopebecomes the default in v3 depends on the feedback here.Use case
Here's a handler that looks correct and isn't:
With ten records in the batch, the log lines from
chargeCustomercarry whicheverorderIdwas appended last.BasePartialProcessor.process()defaultsprocessInParalleltotrueand runsPromise.all(records.map(processRecord)). Logger keeps temporary keys inInvocationScopedslots. Those are only separated per async context whenAWS_LAMBDA_MAX_CONCURRENCYis set, and even then they're separated per invocation, not per record.The downstream case that triggered this RFC is a platform that stamps a
request_idon every DynamoDB item a request writes. The writes flow through a DynamoDB stream, an EventBridge Pipe, a bus and per-consumer SQS queues, to Lambda consumers. Each consumer wants every log line for a record to carry that record'srequest_idas the correlation id. EventBridge can't set SQS message attributes, so the id is inside the body, atdetail.dynamodb.NewImage.request_id.S. Because parallel batches can't do this today, the team moved their consumers to sequential processing as a stopgap.Sequential processing doesn't fully fix it either. Keys appended in record 1 are still there when record 2 starts, because nothing clears them between records.
Today's workarounds:
processInParallel: false. This is slower, and keys still carry over from one record to the next.logger.createChild()per record, passed to every function the handler calls. It works, but it changes the signature of every function that logs.AsyncLocalStoragethe user manages, which means rebuilding what Powertools should provide.Proposal
What users write
The handler has no wrapper and keeps its signature. The two new options sit in the processing options, next to
processInParallel.Semantics
logger.appendKeys({ tenant })called beforeprocessPartialResponseshows up in every record.BatchProcessorSync, and to both FIFO processors.Loggergets record-level keys too.logger.resetKeys()inside a record drops the keys that record added and goes back to the invocation's keys. A record can't wipe keys liketenantfor itself by accident.correlationIdturnsrecordScopeon. Without a scope, a per-record correlation id would leak into the next record.logger.setCorrelationId(record, path), so the Logger resolves it with its owncorrelationIdSearchFn, the same wayinjectLambdaContext({ correlationIdPath })works.SQSEventgives anSQSRecord. It returns the id, andundefinedor an empty string sets nothing.AsyncLocalStoragebehaviour.AWS_LAMBDA_MAX_CONCURRENCYset, record scopes sit inside each invocation's InvokeStore context. Request id, X-Ray trace id and tenant id read the same inside a record as outside it.injectLambdaContext({ resetKeys: true })works unchanged. It runs after the handler, outside any record, and clears invocation keys as it does today.How it works
Commons. We add a record scope next to
InvocationScoped:AsyncLocalStorage<Map<symbol, unknown>>;runInRecordScope(fn), which works for sync and async functions;fork: (parent: T) => TonInvocationScopedOptions.Only slots that declare
forklook at the record scope. Inside a scope, the first access to such a slot stores a fork of the parent value, and later reads and writes in that record use the copy. The parent value comes from the nearest enclosing record scope that has one, and otherwise from the invocation, resolved exactly as today.reset()inside a scope discards the copy, so the next access forks again. Slots withoutforknever read the record scope, so Batch's stores, Metrics' stores and the Logger slots we don't fork behave exactly as they do now.The
AsyncLocalStoragelives onglobalThisunderSymbol.for('powertools.commons.recordScope.v1'), and the firstrunInRecordScopecall creates it. Functions that never open a scope never read it. When a bundle ends up with two copies of commons, they share one scope instead of quietly ignoring each other. Thev1suffix lets us change the shape of the stored map later without breaking older copies.runInRecordScopeandforkare@internal. We export them from the existing@aws-lambda-powertools/commons/utils/invocation-scopedsubpath, which is how Logger and Metrics already importInvocationScoped.Logger. Today
LogAttributesStorekeeps a key map recording, for each key, whether the temporary or the persistent value wins. We replace it with write stamps. Every write gets an increasing number, and when a key is both temporary and persistent, the most recent write wins. Temporary attributes and their stamps live in one slot that declaresfork. Persistent attributes and their stamps stay invocation-wide, as persistent attributes are today. That keeps persistent writes made inside a record visible after it, without any API to reach past the record scope. It also makes the store smaller. The prototype's Logger change is +51 / -63 lines. The fork deep-copies the attributes, becauseappendTemporaryKeysdeep-merges into nested objects in place and a shallow copy would bleed back into the invocation. The public API doesn't change.Batch.
BatchProcessor.processRecordandBatchProcessorSync.processRecordSyncrun the record insiderunInRecordScopewhenrecordScopeorcorrelationIdis set. Both FIFO processors extend these classes and callprocessRecordfrom their own loops, so every loop is covered without touching the loops.try, so a throwing function goes through the normal failure handler.AsyncHandlerNotSupportedErrorfrom the sync processor is still thrown.processPartialResponseandprocessPartialResponseSyncinfer the record type fromevent.Records, so thecorrelationIdfunction's record parameter is typed.BatchProcessingOptions<T, R = any>keeps existing call sites compiling. Loosely typed events give theBaseRecordunion, which the callback has to narrow.loggeroption's type widens, without breaking anyone, toPick<GenericLogger, 'debug' | 'warn' | 'error'> & { setCorrelationId?: (value: unknown, path?: string) => void }.correlationIdis set and the logger has nosetCorrelationId, Batch warns once and carries on.SqsFifoPartialProcessorandSqsFifoPartialProcessorAsyncgain an optional constructor config withlogger. Today they take no arguments.Why opt-in first. Turning this on by default changes behaviour some users may depend on, perhaps without knowing it. Today a key appended in record N is visible in record N+1 when processing sequentially, and keys appended inside records are visible after the batch. We'd consider flipping the default in v3, depending on how people use the option in v2.
Investigation
We started from four independent design write-ups, then built two working prototypes. Both prototypes ran the same 13 acceptance tests and the same benchmark.
The tests cover:
AWS_LAMBDA_MAX_CONCURRENCY, each with two records, keeping their request ids;On
main, 11 of the 13 fail. The two that pass are the partial-failure and metrics checks, which guard against regressions.fork)The benchmark used Node 24 on a shared machine. We ran three rounds one after another; the table shows the best run in ms.
recordScopeoffrecordScopeoncorrelationIdlogger.infooutside any batchappendKeysoutside any batchmetrics.addMetricIn the batch benchmark, each record appends a key, logs twice and awaits once. The cost of the scope is about 7 to 10% of batch time. Outside a batch, Logger calls cost about 2 to 6% more. Metrics didn't change beyond noise.
We then resolved the open points from the first prototype in the proposal's prototype: write stamps, nested inheritance, typed
correlationId, error handling,resetKeys(). It now passes 823 tests, including the 13 acceptance tests and new tests for each point. The source diff is +298 / -81 lines, split as commons +139 / -3, logger +51 / -63 and batch +108 / -15. We ran the benchmark again, taking the median of three runs. The machine wasn't idle, so treat ±5% as noise.logger.infooutside any batchappendKeysoutside any batchrecordScopeoncorrelationIdappendKeysgot faster because each write now reads one slot instead of two.We also tried to avoid reading the
AsyncLocalStoragewhen no scope is open, using a process-wide counter of open scopes. It saved about 15 ns per access, about 0.3% of alogger.infocall. It also broke work that outlives its record: once the counter dropped to zero, a fire-and-forget promise started inside a record went back to reading invocation-level keys. We dropped the counter, and kept the test that caught it.Out of scope
forklater, but flushing would need its own design.appendPersistentKeysinside a record still changes the logger for the whole invocation.runInRecordScopeto users or to other utilities, such as Event Handler or Kafka, in this RFC. If demand shows up, it can go public later without changing the semantics.correlationIdfunction. The function receives the raw record, before any parsing.Potential challenges
forkis separated in every record scope, process-wide. That's what lets a second Logger instance work. It also means a futureforkon some other slot changes behaviour for every Batch user who turned the scope on. We'll document the rule inInvocationScoped, and treat addingforkto a slot as a behaviour change.resetKeys()inside a record goes back to the invocation's keys rather than clearing everything. That's a small difference from whatresetKeys()means outside a batch, and the docs need to say so.eventisn't typed, thecorrelationIdfunction gets theBaseRecordunion and has to narrow it. Annotating the parameter asSQSRecordis rejected, and the error points at theeventargument rather than the callback. We triedNoInferto move the error to the callback, but it brokeany-typed events that annotate the record.InvocationScopedslot. That changes one edge case, whereAWS_LAMBDA_MAX_CONCURRENCYis set and no InvokeStore is installed. There,appendPersistentKeysused to throw straight away, and now the error appears at the first log call instead. Normal imports can't produce that setup, because commons imports@aws/lambda-invoke-store, which installs the store. We don't expect anyone to notice.Dependencies and Integrations
AsyncLocalStoragecomes fromnode:async_hooks, which every supported Lambda Node.js runtime provides.@aws-lambda-powertools/commons,loggerandbatch. Batch already depends on commons and doesn't depend on Logger; that stays true. Batch only callssetCorrelationIdthrough the widened logger type.correlationIdreuses thecorrelationIdSearchFnand@aws-lambda-powertools/logger/correlationIdsearchthat users already configure forinjectLambdaContext.AWS_LAMBDA_MAX_CONCURRENCYis set, record scopes use their ownAsyncLocalStorageand never callInvokeStore.run, so the InvokeStore context and its protected keys are untouched.InvocationScoped.Alternative solutions
B. A Logger-owned scope, reached by Batch through a symbol on the logger. Logger keeps its own module-level
AsyncLocalStorage. Batch calls a symbol-keyed method on the logger passed to the processor. Commons only provides the symbol. We prototyped this and it passes the same tests, with the same performance. It leavesInvocationScopeduntouched, which is its main advantage. We prefer the proposal for four reasons:Treat an open scope as scoped for every
InvocationScopedslot. This was the first idea. It changes the shared lookup in commons so that any open scope separates every slot. It would make Batch'serrorsandfailureMessages, which are written from inside the record, and Metrics' stored metrics look empty or get lost. Opting in per slot avoids that.A wrapper such as
logger.withScope(() => ...). It's easy to build, but every handler has to remember it. Code reached through other modules is only covered if the user wraps at the right level. We'd rather users configure this once on the processor.logger.createChild()per record. This works today, and it's what we'd recommend while this RFC is open. It forces every function that logs to accept a logger argument.Reuse
InvokeStore.runfrom@aws/lambda-invoke-store.run(context, fn)replaces the whole invocation context, protected keys included. Outside multi-concurrency mode it also doesn't isolate anything. It doesn't fit nesting inside an invocation.Turn it on for everyone now. It's nicer DX, but it changes the behaviour described in "Why opt-in first" without a major version.
Acknowledgment
Disclaimer: After creating an issue, please wait until it is triaged and confirmed by a maintainer before implementing it. This will reduce amount of rework and the chance that a pull request gets rejected.
Metadata information for admin purposes, please leave them empty.
Future readers
Please react with 👍 and your use case to help us understand customer demand.
All reactions