Feature request: Tracer should log warning instead of throwing when segment is not found

[danrivett]

Expected Behaviour

Today, for an unknown reason in one of our Lambdas in Production, the Tracer object was unable to retrieve the current Segment from X-Ray.

Because the Segment was attempted to be retrieved in the middy middleware at the beginning of every request (here) it caused every Lambda request to fail until we forced a cold-start of the Lambda, which resolved our problem.

It caused the request to fail because the Tracer throws an error if the Segment returned is undefined.

Unfortunately our Lambda was kept warm for over an hour before we tracked it down and forced a cold-start. In the meantime every request failed (see execution logs below).

My expected behaviour would be that if a Segment could not be retrieved, that it doesn't cause the whole Lambda invocation to fail, which it currently does when using the middy middleware.

Tracing should be done on a best-effort basis, if there is any problem tracing a request it should not cause the main request itself to fail. This particular scenario of getting the Segment is one specific case that could be improved to avoid failing the request, but it's quite possible there may be other code-paths that are vulnerable to causing the main request to fail, particularly if instrumented by the captureLambdaHandler middy middleware.

Current Behaviour

As mentioned above, the Tracer currently throws an error if the Segment returned is undefined, this causes the middy middleware to fail every request, since getSegment() is called in the captureLambdaHandlerBefore function (here).

Code snippet

You could wire in a dummy Tracing provider to return undefined from its getSegment() method, called here.

Steps to Reproduce

We don't know yet what caused aws-xray-sdk-core's getSegment() (here) to return undefined, but if you can simulate that, and use the captureLambdaHandler middy middleware, you will find that it causes the wrapped request to fail.

For us it caused the request to fail until the function was cold-started since getSegment() never started returning a Segment object.

Possible Solution

My suggestion would be to consider updating the Tracer.getSegment() method to log a warning and return a dummy SubSegment if a real segment couldn't be retrieved, similar to how it already does if tracing is disabled.

Something like as follows:

  public getSegment(): Segment | Subsegment {
    if (!this.isTracingEnabled()) {
      return new Subsegment('## Dummy segment');
    }

    const segment = this.provider.getSegment();

    if (segment == null) { // changed from === undefined to be slightly more robust in case null is returned somehow
      // throw new Error('Failed to get the current sub/segment from the context.');
      console.warn('Failed to get the current sub/segment from the context, so failing over to manually create one to allow the request to proceed.');
      return new Subsegment('## Fallback segment (as unable to retrieve existing Segment)');
    }
 
    return segment;
  }

AWS Lambda Powertools for TypeScript version

1.6.0

AWS Lambda function runtime

18.x

Packaging format used

Lambda Layers

Execution logs

2023-03-07T17:08:23.043Z	xxxxxxxxx-xxxx-xxxx-xxxxxxxxxxxxx	ERROR	Error: Failed to get the current sub/segment from the context.
    at Object.contextMissingLogError [as contextMissing] (/var/task/index.js:15505:23)
    at getSegment (/var/task/index.js:15569:49)
    at ProviderService.getSegment (/var/task/index.js:20115:51)
    at Tracer2.getSegment (/var/task/index.js:20539:39)
    at open (/var/task/index.js:20841:32)
    at captureLambdaHandlerBefore (/var/task/index.js:20852:11)
    at runMiddlewares (/var/task/index.js:24918:23)
    at async runRequest (/var/task/index.js:24876:5)

2023-03-07T17:08:23.043Z	xxxxxxxxx-xxxx-xxxx-xxxxxxxxxxxxx	ERROR	Error: Failed to get the current sub/segment from the context.
    at Object.contextMissingLogError [as contextMissing] (/var/task/index.js:15505:23)
    at getSegment (/var/task/index.js:15569:49)
    at ProviderService.getSegment (/var/task/index.js:20115:51)
    at Tracer2.getSegment (/var/task/index.js:20539:39)
    at Tracer2.addErrorAsMetadata (/var/task/index.js:20209:33)
    at captureLambdaHandlerError (/var/task/index.js:20867:18)
    at runMiddlewares (/var/task/index.js:24918:23)
    at runRequest (/var/task/index.js:24902:13)

2023-03-07T17:08:23.044Z	xxxxxxxxx-xxxx-xxxx-xxxxxxxxxxxxx	ERROR	Invoke Error 	{
    "errorType": "Error",
    "errorMessage": "Failed to get the current sub/segment from the context.",
    "originalError": {
        "errorType": "Error",
        "errorMessage": "Failed to get the current sub/segment from the context.",
        "stack": [
            "Error: Failed to get the current sub/segment from the context.",
            "    at Tracer2.getSegment (/var/task/index.js:20541:17)",
            "    at open (/var/task/index.js:20841:32)",
            "    at captureLambdaHandlerBefore (/var/task/index.js:20852:11)",
            "    at runMiddlewares (/var/task/index.js:24918:23)",
            "    at async runRequest (/var/task/index.js:24876:5)"
        ]
    },
    "stack": [
        "Error: Failed to get the current sub/segment from the context.",
        "    at Tracer2.getSegment (/var/task/index.js:20541:17)",
        "    at Tracer2.addErrorAsMetadata (/var/task/index.js:20209:33)",
        "    at captureLambdaHandlerError (/var/task/index.js:20867:18)",
        "    at runMiddlewares (/var/task/index.js:24918:23)",
        "    at runRequest (/var/task/index.js:24902:13)"
    ]
}

[dreamorosi]

Hi @danrivett thank you for reporting this, I'll review the report tomorrow morning (EMEA time zone) and write here my findings.

If needed after finding and applying a fix, I'm open to do an emergency release to avoid further outages.

[danrivett]

Thanks for such a quick response @dreamorosi especially given your timezone.

For now we're looking at deploying we've deployed the following workaround to wrap Tracer.getSegment() based off my suggested fix in this ticket, so that should avoid the need for an emergency fix and allow more time to evaluate the best solution.

export class CustomTracer extends Tracer {
  public constructor(options?: TracerOptions) {
    super(options);

    this.getSegment = this.getSegment.bind(this);
    this.createFallbackSubSegment = this.createFallbackSubSegment.bind(this);
  }

  getSegment(): Segment | Subsegment {
    try {
      return super.getSegment();
    } catch (error) {
      console.error(
        'Failed to get the current sub/segment from the context, so failing over to manually create one to allow the request to proceed.',
        error
      );
      return this.createFallbackSubSegment();
    }
  }

  protected createFallbackSubSegment(): Subsegment {
    return new Subsegment(
      '## Fallback segment (as unable to retrieve existing Segment)'
    );
  }
}

Note: This external fix is slightly different from the one suggested above because I'm wrapping the whole Tracer.getSegment() method call which is currently throwing an error, rather than altering how that method responds to undefined being returned from this.provider.getSegment().

[dreamorosi]

So, I've started looking into this and on the Powertools' side, I was able to reproduce the behavior with this unit test case:

test('when no subsegment is returned, everything blows up', async () => {

  // Prepare
  const tracer: Tracer = new Tracer();
  jest.spyOn(tracer.provider, 'getSegment')
    .mockImplementationOnce(() => undefined);
  const lambdaHandler: Handler = async (_event: unknown, _context: Context) => ({
    foo: 'bar'
  });
  const handler = middy(lambdaHandler).use(captureLambdaHandler(tracer));

  // Act & Assess
  await expect(handler({}, context)).rejects.toThrowError(
    Error('Failed to get the current sub/segment from the context.')
  );

});

Now, by looking at the logs in the OP, and looking at the call stack in them, it seems that the first getSegment call that failed was the one in the before lifecycle stage of the middleware (here), as opposed to the one linked in the OP which is in the after phase (see below, line annotated with /// HERE ///):

2023-03-07T17:08:23.043Z	xxxxxxxxx-xxxx-xxxx-xxxxxxxxxxxxx	ERROR	Error: Failed to get the current sub/segment from the context.
    at Object.contextMissingLogError [as contextMissing] (/var/task/index.js:15505:23)
    at getSegment (/var/task/index.js:15569:49)
    at ProviderService.getSegment (/var/task/index.js:20115:51)
    at Tracer2.getSegment (/var/task/index.js:20539:39)
    at open (/var/task/index.js:20841:32)
    at captureLambdaHandlerBefore (/var/task/index.js:20852:11) <--- /// HERE ///
    at runMiddlewares (/var/task/index.js:24918:23)
    at async runRequest (/var/task/index.js:24876:5)

This points to the fact that for some reason the X-Ray SDK returned undefined, which is strange.

I need to investigate a bit further to try to understand why that could have happened, but as far as I remember this shouldn't happen unless AWSXRay.getSegment (here) was called outside of the context of a function invocation. However the call stacks in the logs you shared don't seem to indicate that.

I agree that the behavior of throwing an error is not explicitly documented, and that in most cases the current behavior might not be the best/desired one. However, strictly speaking I'm not sure yet if this should be marked as bug, given that Tracer behaved as it was supposed to (aka throw an error when no segment is returned).

With that said, I'm open to discuss and explore the possibility to change this into a warning like you suggested, or to at least give users a way to decide the behavior similar to what the X-Ray SDK does with the setContextMissingStrategy method.

In the meanwhile, would you be open to share the final log of a few of these faulty executions? I'm looking to see, if possible, the report log and see if the tracing-related info were present. If you prefer to do so in a less public forum, you can also email them at aws-lambda-powertools-feedback@amazon.com.

[dreamorosi]

Would like to amend a section of my previous comment:

I need to investigate a bit further to try to understand why that could have happened, but as far as I remember this shouldn't happen unless AWSXRay.getSegment (here) was called outside of the context of a function invocation. However the call stacks in the logs you shared don't seem to indicate that.

After looking again at the logs you provided, and specifically at the call stack, we can see in the first line of each log error this line:

at Object.contextMissingLogError [as contextMissing] (/var/task/index.js:15505:23)

Based on this entry of the call stack, it seems that the root cause of the issue is the fact that both the X-Ray SDK and Tracer were not able to find any trace data. This usually happens when trying to retrieve a segment or perform actions on it outside of the context of an invocation.

To continue with the investigation, could you please also provide two more pieces of info:

• Which version of the X-Ray SDK are your Lambda functions running? I'm asking this because in 3.4.1 the SDK changed its behavior around missing context from throwing a runtime error to logging (PR here). Based on the call stack it seems you might be using that version (for context, Powertools still pins the previous one)
• Any chance you could also share the high level structure of your function, the exported handler (not its content), and how you're using the middleware (plural)? Based on what I discussed above it seems that somehow the middleware is running outside of the Lambda context, although it's very strange and shouldn't happen

---

More details on how the AWS X-Ray SDK (from now on referred as SDK) resolves the trace context/data, note that all this happens upstream of Powertools.

1. The first time that the SDK is imported, an IFEE defined here is called.
2. This function configures the SDK to works in Lambda by setting some configs.
3. After that, a namespace and context are created, and the first facade segment is set
4. Up to this point, the facade segment is not valid and it's a dummy one as we are still outside of the scope of the actual function handler

Now, the codepath that leads to the stack in your logs, as far as I know, can be triggered only by first calling one of these three methods of the SDK:

• getSegment, which corresponds to this implementation
• setSegment, which corresponds to this implementation
• resolveSegment, implemented here, which you probably won't be using in userland and that is usually called by one or the other two under the hood

All these methods are related to segment and context and the reason why is that is because the SDK stores the current segment in this context object (from this package which acts as custom implementation/polyfill of Async Hook present in more modern Node.js versions).

In a "regular" execution, the codepath executed should be this, which essentially tells the SDK to create a new facade segment, this time using the info coming from the Trace data present in the environment.

If we look at the logic of these three methods, the error related to the contextMissing can be triggered only if said methods were called outside of the context of a lambda execution, i.e.

import { getSegment } from 'aws-xray-sdk-core`;

const segment = getSegment(); // <- This will trigger a context missing

export const handler = () => {};

I know the example above is extremely trivial and simplistic, but is there any chance that this could be happening somewhere in your code, either outside of the handler or in middleware that run before there any chance that

[danrivett]

Thank you so much @dreamorosi for taking such a timely and detailed look into this bug report. It really is greatly appreciated.

It is still early on the west coast here, and we still have some actions remaining from the outage yesterday that I need to attend to first, but I will respond later today with more information that you requested. I will post what I can here, and the rest I will email.

However three brief updates:

1. We aren't calling X-Ray directly, in fact I had to add the aws-xray-sdk-core package to our package.json file in order to code the workaround solution above and manually new up a Subsegment object.
2. We do have other middleware installed, namely other Powertools middleware such as injectLambdaContext provided by the Logger, but also custom middleware.

• As examples, some of these middleware translate errors thrown of a certain type (ClientError in our case) into being a return error object rather than throwing the error (this is because it's invoked by AppSync and we want to be able to return the equivalent of 400s without marking our Lambdas as in error when they work as designed)
• Other middleware also has global input policing to ensure that certain fields match our rules (because AppSync doesn't allow for custom scalar types (such as these common ones) 🙏
• Therefore it's possible and we believe did happen in our cases detected so far that another middleware layer threw an error. However there are many other invocations that this has happened that hasn't caused this reported issue, so if that is affecting this, it doesn't affect it very often for us.
• And I want to be clear that although an error was thrown by another middleware for one request, the Tracer middleware continued to fail for all requests until we manually redeployed it an hour later and cold-started it.
  • The key thing here though is the error becomes permanent until the function is destroyed and a new one is cold started. All our subsequent functions that passed middleware checks failed with the reported error above.

My final point though, is that regardless of the above, I think there is a design decision that needs to be carefully thought through and made: should an error in any instrumentation middleware - such as this X-Ray one, but not limited to that - be severe enough to warrant not executing the wrapped underlying function successfully?

One can argue both sides to this, but as I mentioned above I view instrumentation as best-effort and auxillary, and shouldn't itself prevent the underlying function from executing if it encounters an error.

This could of course be configurable, and although I wouldn't recommend it, the default could be to block the execution of the underlying function if it encounters an error, as there are valid reasons for this. As I mentioned we have middleware with polices the input, so of course we want those errors to block execution of the underlying function. But I don't view the failure of tracing instrumentation as cause for blocking the execution of the underlying function. I would much rather log a warning and alert off of that for us to investigate.

So regardless of the root cause of why this.provider.getSegment() returned undefined in Tracer.getSegment(), I think a decision needs to be made and documented about whether the Powertools instrumentation middleware should try to run on a best-effort basis, and in that case it should not choose to throw errors that will prevent the underlying function from executing, unless absolutely necessary.

To put this in context, there was a real customer impact for over an hour yesterday because of the errors being thrown, I'd argue not tracing those requests and allowing them to proceed in this error scenario is a much better alternative, which is why I am putting so much effort in explaining my reasoning.

We can always and should work to fix the root cause of issues (that's part of my investigation today), but there will always be bugs and so I feel we have to decide if we want to design middleware that gives the underlying request the greatest chance of success and so tolerate certain error scenarios what shouldn't but can happen.

One final addendum: The workaround above seems to be working well for us, overnight we had 8 function invocations out of 12,000 which encountered not being able to resolve the Segment, but they failed over and didn't cause subsequent executions to fail until the next cold start.

Interesting that those invocations were clustered too, which is something I'll look into. (Update: they aren't, see comment below)

Thanks again @dreamorosi your huge efforts on this library and helping customers is not unnoticed and very appreciated.

[dreamorosi]

Thank you for the additional details, I just wanted to clarify that my investigation for a root cause is not to defer responsibility to another package or to your code but only to try to identify the actual issue that caused the outage, and try to understand if this is something that is inherent to Tracer, and if so, that should be fixed so that it doesn't affect other customers.

The above is separate and independent from the fact that as you say tracing throwing an error should not break the whole middleware stack. I agree with that and after looking at the X-Ray SDK, which recently changed their default behavior to just log when this happens, I think we should do the same.

I'm happy to move forward with this fix, however if you are available I'd still like to understand what caused the issue. I'm concerned that if we apply the fix and just log, we'll be patching the behavior (aka the error being thrown), but we wouldn't be fixing the actual issue that caused it. However I also understand that you might have other priorities or not be interested in dedicating time to this, so if that's the case I 100% understand and there's no expectation whatsoever from our side on you doing that.

[danrivett]

Thanks @dreamorosi I definitely want to provide additional info to help determine the root cause - we ourselves want to also understand that for similar reasons. My gut is there is an edge condition somewhere, possibly in the X-Ray SDK, but could easily be outside that too, it's too early for me to draw many conclusions.

I've been continuing to investigate, and it's still ongoing, but I do have some additional information I've uncovered that I can share here below.

But first I want to clarify an incorrect observation I made above (that's the danger of reporting timely but prematurely) - those 8 function invocations were not clustered, and in fact were 4 function invocations and each error had two log entries that matched by my query (one from the log message from aws-xray-sdk-core itself, and the other from our failover logged warning).

I thought it was worth updating on that as those 4 cases were isolated and not clustered as I first thought.