powertools-lambda-typescript icon indicating copy to clipboard operation
powertools-lambda-typescript copied to clipboard

Feature request: avoid tracing API calls made during init (top-level `await`)

Open dreamorosi opened this issue 1 year ago • 5 comments

Use case

Currently when using the Parameters and Tracer utility together, and with top-level await (like shown below) used in a certain order an error is logged (but not thrown) informing that the X-Ray SDK is unable to find a trace root (expected).

import { Tracer } from '@aws-lambda-powertools/tracer';
import { Logger } from '@aws-lambda-powertools/logger';
import { getParameter } from '@aws-lambda-powertools/parameters/ssm';

/**
 * note that tracer is instantiated before the `getParameter` call
 * from this point on, http calls (including the ones with AWS SDK) are traced
 */
const tracer = new Tracer();
const logger = new Logger();
const ssmParameter = await getParameter('/layers/powertools-layer-arn');

export const handler = async () => {
  logger.info('param', { ssmParameter });
  
  return {
    statusCode: 200,
    body: JSON.stringify("Hello, World!"),
  };
};

This is the log emitted by the AWS X-Ray SDK, which attempts to trace the request made

2024-04-19T21:34:27.204Z        undefined       ERROR   Error: Missing AWS Lambda trace data for X-Ray. Ensure Active Tracing is enabled and no subsegments are created outside the function handler.
    at Object.contextMissing (file:///var/task/index.mjs:7:16736)
    at e.resolveLambdaTraceData (file:///var/task/index.mjs:7:36770)
    at Object.getSegment (file:///var/task/index.mjs:7:17544)
    at Object.resolveSegment (file:///var/task/index.mjs:7:17251)
    at n (file:///var/task/index.mjs:7:95499)
    at s (file:///var/task/index.mjs:7:97066)
    at /var/runtime/node_modules/@aws-sdk/node_modules/@smithy/node-http-handler/dist-cjs/index.js:233:19
    at new Promise (<anonymous>)
    at _NodeHttpHandler.handle (/var/runtime/node_modules/@aws-sdk/node_modules/@smithy/node-http-handler/dist-cjs/index.js:189:12)
    at async /var/runtime/node_modules/@aws-sdk/node_modules/@smithy/middleware-serde/dist-cjs/index.js:33:24
START RequestId: 1ae7c9e3-37d1-4110-b8c0-cdb63b70b69d Version: $LATEST
{"level":"INFO","message":"param","sampling_rate":0,"service":"service_undefined","timestamp":"2024-04-19T21:34:27.305Z","xray_trace_id":"1-6622e362-563b8ad23b746432303d77c6","ssmParameter":"arn:aws:lambda:eu-west-1:123456789101:layer:AWSLambdaPowertoolsTypeScriptV2:5"}
END RequestId: 1ae7c9e3-37d1-4110-b8c0-cdb63b70b69d
REPORT RequestId: 1ae7c9e3-37d1-4110-b8c0-cdb63b70b69d  Duration: 50.72 ms      Billed Duration: 51 ms  Memory Size: 128 MB     Max Memory Used: 94 MB  Init Duration: 553.91 ms
XRAY TraceId: 1-6622e362-563b8ad23b746432303d77c6       SegmentId: 1e9f991047253160     Sampled: true

This is expected in the sense that trace data is available only within the handler scope and made available by the AWS Lambda service only when invoking your function.

This is not a runtime error (which is also why this is a feature request and not a bug) but nevertheless it's a nuisance and we should try to find a way to handle this case without making the AWS X-Ray SDK log the error.

Note that swapping the order of the Tracer instantiation and the Parameters call, like below, fixes the issue:

const ssmParameter = await getParameter('/layers/powertools-layer-arn');
// this is fine because http tracing starts after this point and the call already happened
const tracer = new Tracer();

Solution/User Experience

The experience for customers should stay as-is and the change should be backwards compatible.

Alternative solutions

No response

Acknowledgment

Future readers

Please react with 👍 and your use case to help us understand customer demand.

dreamorosi avatar Apr 19 '24 21:04 dreamorosi

Just landed here as I was wondering why I'm seeing that error.

My use case isn't necessary valid. I was just testing out various (premature 😅 ) optimizations where I call one async function (that essentially initializes a Promise that starts making HTTP calls) before the handler function and then later in the handler I actually await the value of that Promise. I'm not yet even sure if I that makes any real difference, but generally speaking I can see think of various reasons of doing similar things.

aripalo avatar Apr 27 '24 23:04 aripalo

Is there maybe a workaround to disable the logging of that error? This error message clutters our logs 😅.

HaaLeo avatar Jul 10 '24 12:07 HaaLeo

The log comes from the X-Ray SDK for Node.js as we can see from the stack trace above.

I haven't tested it, but I think setting the AWS_XRAY_CONTEXT_MISSING env var to IGNORE_ERROR as specified here might do the trick.

dreamorosi avatar Jul 10 '24 13:07 dreamorosi

Thx for the answer, I'll try that.

HaaLeo avatar Jul 10 '24 13:07 HaaLeo

I can confirm that with the environment variable AWS_XRAY_CONTEXT_MISSING set to IGNORE_ERROR the error is no longer logged 👍🏼. Thank you for the hint @dreamorosi.

HaaLeo avatar Jul 10 '24 14:07 HaaLeo

I will be opening a PR that updates our Tracer utility to automatically set the AWS_XRAY_CONTEXT_MISSING environment variable to IGNORE_ERROR by default, whenever a value is not specified by customers.

I've been investigating alternatives and given that the error comes from the feature that instruments http requests made by the underlying https method within the AWS SDK, fixing this would require us to write our own logic for this type of instrumentation, which is out of scope for the time being.

I think this is a middle ground that will help remove the clutter while still allowing flexibility to revert to the original behavior. The AWS X-Ray SDK was never thought with top-level await in mind after all.

dreamorosi avatar Sep 12 '24 21:09 dreamorosi

⚠️ COMMENT VISIBILITY WARNING ⚠️

This issue is now closed. Please be mindful that future comments are hard for our team to see.

If you need more assistance, please either tag a team member or open a new issue that references this one.

If you wish to keep having a conversation with other community members under this issue feel free to do so.

github-actions[bot] avatar Sep 12 '24 22:09 github-actions[bot]

This is now released under v2.8.0 version!

github-actions[bot] avatar Sep 16 '24 12:09 github-actions[bot]