Aws-xray-sdk-node: Annotation not set for Lambda (not using Express)

[chearmstrong]

Hi.

In my lambda handler, I'm trying to set an annotation on a subsegment. I'm not using express.

const sub = AWSXRay.getSegment().addNewSubsegment('my-handler')

// Rest of my code...

sub.addAnnotation('response', JSON.stringify(response))

I can't see this set anywhere though. What am I missing?

Thanks in advance.

[willarmiros]

Hi @chearmstrong,
There are (at least) two possibilities here. The first is you are not closing your subsegment with sub.close(error) - which you must to guarantee all its attributes are included. The other is that this is a similar issue to #219 in which there are asynchronous functions in your code which cause the segment for the function to be ended prematurely, before your addAnnotation is reached. Please provide some more repro code to help determine which root cause is more likely.

[chearmstrong]

Thanks for the reply @willarmiros - here's more code. I suspect it's the async thing. Is there a workaround for this atm?

I changed it to use captureAsyncFunc which is better - on some requests I see everything. However, not on others. Interestingly, it's a request where I also call SQS which seems to be missing stuff.

const handler = async event => {
  return AWSXRay.captureAsyncFunc('my-handler', subSegment => {
    subSegment.addAnnotation('body', JSON.stringify(event.body))

    return handleEvent(event)
      .then(response => {
        subSegment.addAnnotation('response', JSON.stringify(response))
        subSegment.close()

        return getSuccessResponse(response)
      })
      .catch(error => {
        subSegment.close(error, false)

        return getErrorResponse(error)
      })
  })
}

[willarmiros]

Hi @chearmstrong,
What's interesting is that I could not reproduce your issue with some generic handleEvent async function. Maybe it's because mine was a little too fast, but not sure exactly.

What happens in general in these types of situations is execution hits an async function like handleEvent and that function executes and returns quickly, as it should, because its callback (.then in this case) will eventually be added to the task queue to be executed later. However because handleEvent has finished executing, the top-level handler has reached the end of its execution and can now return its promise. The Lambda function correctly waits for this promise to be resolved before terminating, however I believe the X-Ray segment is sent before the promise is resolved, meaning the actions like adding that annotation are not reflected in the prematurely sent segment.

I hope this makes some sense. We are investigating this issue with Lambda currently. I will update this thread as we learn more.

[willarmiros]

Hi @chearmstrong,
Are you still experiencing this error? Here's the code I'm using to reproduce on Lambda, with node 12.x and X-Ray SDK 3.0.0:

const AWSXRay = require('aws-xray-sdk');

exports.handler = async event => {
  return AWSXRay.captureAsyncFunc('my-handler', subSegment => {
    subSegment.addAnnotation('body', JSON.stringify(event));

    return handleEvent(event)
      .then(response => {
        console.log('response=' + response);
        subSegment.addAnnotation('response', response);
        subSegment.close();

        return response;
      })
      .catch(error => {
        subSegment.close(error, false);

        return error;
      });
  });
};

async function handleEvent(event) {
  let promise = new Promise((resolve, reject) => {
    setTimeout(() => resolve("done!"), 1000);
  });

  let result = await promise;
  return result;
}

Perhaps the use of cls-hooked in 3.0.0 helped? I've consistently seen the correct annotation added when trying to reproduce the error, so please let me know if you can get the error reproduced more consistently.

[chearmstrong]

Just been checking this one with v3 seems to be working as expected now (on our staging env at least). Will update prod with sees a lot of requests and monitor it - will come back if have an more issues.