aws / aws-xray-sdk-node

The official AWS X-Ray SDK for Node.js.
Apache License 2.0
273 stars 156 forks source link

Failed to get the current sub/segment from the context #415

Open atlanteh opened 3 years ago

atlanteh commented 3 years ago

I have a NodeJs service (using express) that we are now trying to monitor with Xray. For some reason, every time a new request is issued, I get the following error:

[ERROR] Error: Failed to get the current sub/segment from the context.
    at Object.contextMissingLogError [as contextMissing] (/Users/ronagar/src/node_modules/aws-xray-sdk-core/lib/context_utils.js:26:19)
    at Object.getSegment (/Users/ronagar/src/node_modules/aws-xray-sdk-core/lib/context_utils.js:102:45)
    at tryGetCurrentSegment (/Users/ronagar/src/node_modules/aws-xray-sdk-core/lib/patchers/promise_p.js:63:25)
    at Promise.then (/Users/ronagar/src/node_modules/aws-xray-sdk-core/lib/patchers/promise_p.js:20:12)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)

There's no additional stack, so there's really no way to determine where this issue comes from. After hours of debugging I'm still clueless as to where the culprit is. Every time I change something, the error pops up some place else. As you can see the error happens in the promise patching. when disabling capturePromise the error goes away, but we need this as we have many promises & external calls running during the request. One thing that I keep noticing is that if I see the error happens when calling a specific function. I change this function code to async/await and suddenly this goes away. but I do have other functions that do have regular promises and they don't crash. Is there any way to identify what is the culprit? how to resolve this?

Stack that I think relevant: NodeJs 12.17.0 aws-sdk 2.294.0 aws-xray-sdk 3.3.1 axios 0.21.2 bluebird 3.7.2

srprash commented 3 years ago

Hi @atlanteh The error happens due to a parent segment/subsegment not being in the current context when the promise is being captured. Just to be sure there's a segment, are you instrumenting incoming request to your express application?

You also mentioned that you see this error with a specific function using promise while not with others. Can you post snippets of the problematic and non-problematic functions?

Thanks

atlanteh commented 3 years ago

Hey, @srprash, thanks for you reply. Yes I'm using the express middleware. By specific function I mean that when debugging I'm trying to step in to some arbitrary function A, and suddenly this error pops up with no stack trace. Then, I change that function from promise based to async/await and when debugging again I'm able to step into and out of the function. and then the error pops up on another function. I'm changing that one to async/await as well and then again it pops up some place else. After fixing several functions like this, now it's popping up inside axios.post which naturally I can't convert to async/await. For now our resolution is to just not use capturePromise and now everything works as intended, though according to the docs some subsegments may be reported as siblings. It may bug us in the future, but currently we have no other choice

willarmiros commented 3 years ago

@atlanteh if you don't want this error to come up while debugging please set the AWS_XRAY_CONTEXT_MISSING environment variable to LOG_ERROR or IGNORE_ERROR. For more info, see the readme.

atlanteh commented 3 years ago

@willarmiros actually the error shows without debugging. I'm debugging to try and figure out why this error happens.

willarmiros commented 3 years ago

@atlanteh the error arises when the X-Ray SDK attempts to find a segment or subsegment in the current context and fails to. In this case, the Promise patcher is trying to get the current segment here:

https://github.com/aws/aws-xray-sdk-node/blob/b616b51a58b3956655ad6db9d73a420425190c84/packages/core/lib/patchers/promise_p.js#L63

This is likely because you're using a promise outside of the route mapping path of your Express application. There is only an automatically available segment in your context within the route mapping logic of your express app.

One thing that I keep noticing is that if I see the error happens when calling a specific function.

Is this function within within your route handling logic? Could you share a representative snippet of what your instrumented app looks like?

atlanteh commented 3 years ago

@willarmiros I know, and I'm sure we're running inside the context of a request. As I said this is not a specific function. it's just some random functions. Our services are pretty complex and run multiple things, including running some metrics in the background (which are also run inside xray namespace. could this somehow cause this somehow? BTW we also get some of these issues:

[ERROR] Error: Failed to get the current sub/segment from the context.
at Object.contextMissingLogError [as contextMissing] (/opt/it/lib/node_modules/itc-landlord-service/node_modules/aws-xray-sdk-core/lib/context_utils.js:26:19)
at Object.getSegment (/opt/it/lib/node_modules/itc-landlord-service/node_modules/aws-xray-sdk-core/lib/context_utils.js:102:45)
at Object.resolveSegment (/opt/it/lib/node_modules/itc-landlord-service/node_modules/aws-xray-sdk-core/lib/context_utils.js:83:19)
at captureOutgoingHTTPs (/opt/it/lib/node_modules/itc-landlord-service/node_modules/aws-xray-sdk-core/lib/patchers/http_p.js:97:33)
at Object.captureHTTPsRequest [as request] (/opt/it/lib/node_modules/itc-landlord-service/node_modules/aws-xray-sdk-core/lib/patchers/http_p.js:200:12)
at features.constructor.handleRequest (/opt/it/lib/node_modules/itc-landlord-service/node_modules/aws-sdk/lib/http/node.js:45:23)
at sendRequest (/opt/it/lib/node_modules/itc-landlord-service/node_modules/aws-sdk/lib/util.js:896:12)
at processTicksAndRejections (internal/process/task_queues.js:79:11)

We're using bluebird in some of our modules and infra. could this be causing it?

willarmiros commented 3 years ago

That error is similar, because it is also failing to find a segment in the current context, however it is triggered by an outgoing instrumented HTTP request, specifically one from the AWS SDK. You mentioned that you're sending some metrics in the background, so if those are being sent using the AWS SDK (e.g. the CloudWatch client) out-of-band with your incoming requests, I'd say that's very likely why you're seeing these errors. It's possible that occasionally, when sending metrics, there is no active segment from handling an express request available, so this error is raised.

There is no easy way of resolving this; you either have to wrap all of the out-of-band http requests with a new segment, or ignore these errors, or set the X-Ray log level to SILENT.

atlanteh commented 3 years ago

@willarmiros we removed the promise patcher and the errors stopped, however in hide payload services, about +-4 times a day, in the context of the request, the segment is undefined:

// app bootstrap
if (useXray) {
  XRay.config([XRay.plugins.EC2Plugin, XRay.plugins.ECSPlugin]);
  XRay.captureAWS(require('aws-sdk'));
  XRay.captureHTTPsGlobal(require('http'));
  XRay.captureHTTPsGlobal(require('https'));
}

if (useXray) {
  app.use(XRay.express.openSegment('myServiceName'))
}

app.use((req, res, next) => {
  const context = {} // creating our internal context

  if (useXray) {
    const segment = XRay.getSegment();
    XRayUtils.addDefaultSegmentInfo(segment, config, context); // adding some custom metadata
  }

  next();
})

// some more middlewares, including security middleware
app.use((req, res, next) => {
  const isValidRequest = true;
  if (isValidRequest) {
    next()
  } else {
    res.status(401).send()
  }
});

app.use((req, res, next) => {
  if (useXray) {
    const segment = XRay.getSegment();
    // HERE SEGMENT IS UNDEFINED
  }
  next();
});

// ...routes router

if (useXray) {
  app.use(XRay.express.closeSegment());
}

app.use(errorHandler);

Any idea how that might happen? how can we solve this?

stale[bot] commented 2 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs in next 7 days. Thank you for your contributions.

kevin-homstar commented 2 weeks ago

The fix for me was the env var AWS_XRAY_CONTEXT_MISSING set to IGNORE_ERROR. Background i'm not even using express, this is from using SDK to get specifics from AWS for integration e2e testing once system is deployed. It only appeared recently after an SDK up version in the project.

The tests actually complete and are successful, but because of the console.error log the pipeline fails as these was standard error.

` console.error

229 | 2024-11-12 22:59:19.983 +00:00 [ERROR] Error: Failed to get the current sub/segment from the context. 230 | at Object.contextMissingLogError [as contextMissing] (/codebuild/output/src332162126/src/node_modules/aws-xray-sdk-core/dist/lib/context_utils.js:22:27) 231 | at Object.getSegment (/codebuild/output/src332162126/src/node_modules/aws-xray-sdk-core/dist/lib/context_utils.js:89:53) 232 | at Object.resolveSegment (/codebuild/output/src332162126/src/node_modules/aws-xray-sdk-core/dist/lib/context_utils.js:71:25) 233 | at captureOutgoingHTTPs (/codebuild/output/src332162126/src/node_modules/aws-xray-sdk-core/dist/lib/patchers/http_p.js:84:37) 234 | at captureHTTPsRequest (/codebuild/output/src332162126/src/node_modules/aws-xray-sdk-core/dist/lib/patchers/http_p.js:175:16) 235 | at /codebuild/output/src332162126/src/node_modules/@smithy/node-http-handler/dist-cjs/index.js:349:19 236 | at new Promise () 237 | at _NodeHttpHandler.handle (/codebuild/output/src332162126/src/node_modules/@smithy/node-http-handler/dist-cjs/index.js:283:12) 238 | at async /codebuild/output/src332162126/src/node_modules/@aws-sdk/credential-provider-http/dist-cjs/fromHttp/fromHttp.js:60:28 239 | at async /codebuild/output/src332162126/src/node_modules/@aws-sdk/credential-provider-http/dist-cjs/fromHttp/retry-wrapper.js:8:24 240 | at async /codebuild/output/src332162126/src/node_modules/@smithy/property-provider/dist-cjs/index.js:97:27 241 |   242 | at Object.error (node_modules/aws-xray-sdk-core/dist/lib/logger.js:17:17) 243 | at Object.contextMissingLogError [as contextMissing] (node_modules/aws-xray-sdk-core/dist/lib/context_utils.js:23:36) 244 | at Object.getSegment (node_modules/aws-xray-sdk-core/dist/lib/context_utils.js:89:53) 245 | at Object.resolveSegment (node_modules/aws-xray-sdk-core/dist/lib/context_utils.js:71:25) 246 | at captureOutgoingHTTPs (node_modules/aws-xray-sdk-core/dist/lib/patchers/http_p.js:84:37) 247 | at captureHTTPsRequest (node_modules/aws-xray-sdk-core/dist/lib/patchers/http_p.js:175:16) 248 | at node_modules/@smithy/node-http-handler/dist-cjs/index.js:349:19 249 | at _NodeHttpHandler.handle (node_modules/@smithy/node-http-handler/dist-cjs/index.js:283:12) 250 | at async /codebuild/output/src332162126/src/node_modules/@aws-sdk/credential-provider-http/dist-cjs/fromHttp/fromHttp.js:60:28 251 | at async /codebuild/output/src332162126/src/node_modules/@aws-sdk/credential-provider-http/dist-cjs/fromHttp/retry-wrapper.js:8:24 252 | at async /codebuild/output/src332162126/src/node_modules/@smithy/property-provider/dist-cjs/index.js:97:27 `