Tests failing for `@aws-sdk/client-sqs >=3.316`

[pichlermarc]

What version of OpenTelemetry are you using?

Current revision on main

What version of Node are you using?

Node 16, 18

What did you do?

npm run test-all-versions in @opentelemetry/instrumentation-aws-sdk

What did you expect to see?

Tests pass.

What did you see instead?

Tests fail for @aws-sdk/client-sqs >=3.316

Additional context

Run for Node 16: https://github.com/open-telemetry/opentelemetry-js-contrib/actions/runs/4787435108/jobs/8512667684
Run for Node 18: https://github.com/open-telemetry/opentelemetry-js-contrib/actions/runs/4787435108/jobs/8512667928

[pichlermarc]

cc @carolabadeer would you mind looking into this as you're listed as the code owner? 🙂 This could mean that the instrumentation is not producing the expected telemetry for the most recent versions of @aws-sdk/client-sqs

I'm able to produce this locally by installing either 3.316.0 or 3.319.0.
3.315.0 on the other hand works fine 🤔

[carolabadeer]

Thanks for raising this @pichlermarc! I will take a look into what could be causing this issue

[dyladan]

labeling p4 as this does not affect users

[pichlermarc]

@carolabadeer any update?

[carolabadeer]

Currently working with the AWS SDK for JS team to identify possible issues in the changes between @aws-sdk/client-sqs v3.315 and v3.316 that could be causing this test failure. Will post updates here on findings and progress

[carolabadeer]

While waiting I also looked into the behavior in the unit tests and found that there are two spans being used (not sure if they are meant to be the same) - a test span and a callback span.

The callback span is the one whose attributes are being checked in the unit test that is failing. In that span, the test is checking for a SemanticAttributes.MESSAGING_OPERATION attribute but cannot find one. This span seems to be wrapping an S3 CreateBucket call. These are it's attributes:

{
  'aws.operation': 'createBucket',
  'aws.signature.version': 's3',
  'aws.service.api': 'S3',
  'aws.service.identifier': 's3',
  'aws.service.name': 'Amazon S3',
  'rpc.system': 'aws-api',
  'rpc.method': 'CreateBucket',
  'rpc.service': 'S3',
  'aws.region': 'us-east-1',
  'aws.request.id': '0000000000000',
  'http.status_code': 200
}

Since this is an S3 call, there shouldn't be a messaging.operation atttribute, which is the correct behavior.

The test span, on the other hand, is the one wrapping the SQS ReceiveMessage call. That span contains the correct messaging.operation attribute:

{
  'rpc.system': 'aws-api',
  'rpc.method': 'ReceiveMessage',
  'rpc.service': 'SQS',
  'messaging.system': 'aws.sqs',
  'messaging.destination_kind': 'queue',
  'messaging.destination': 'otel-demo-aws-sdk',
  'messaging.url': 'https://sqs.us-east-1.amazonaws.com/731241200085/otel-demo-aws-sdk',
  'messaging.operation': 'receive',
  'aws.region': 'us-east-1',
  'http.status_code': 200
}

These are my findings so far, but I am still curious about 2 questions:

1. Why is the callback span only being used in this messaging.operation attribute test and not in any other place? I was able to solve this issue and get the test to pass by using

          // where span.attributes represents the attributes of the test span shown above 
          expect(span.attributes[SemanticAttributes.MESSAGING_OPERATION]).toMatch(
            MessagingOperationValues.RECEIVE
          );

instead of

          expect(attributes[SemanticAttributes.MESSAGING_OPERATION]).toMatch(
            MessagingOperationValues.RECEIVE
          );

@blumamir since you added this unit test, maybe you can give us some insight?

2. Still unsure about how/why this issue did not present itself earlier. The implementations for adding the MESSAGING_OPERATION attribute and the unit tests have not had any recent changes, and I am not yet sure about the correlation between the @aws-sdk/client-sqs version bump and this test failure.

[github-actions]

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

[blumamir]

This span seems to be wrapping an S3 CreateBucket call. These are it's attributes:

why are we seeing S3 CreateBucket span in this test?

1. Why is the callback span only being used in this messaging.operation attribute test and not in any other place? I was able to solve this issue and get the test to pass by using

So what this part actually asserts is that the callback itself is being invoked with the receive span set as the active span for the callback invocation. The issue is that any operations triggered inside the callback, like calling deleteMessage or executing db queries - those will create new spans and the parent for them will be the span we get back from context.active() const receiveCallbackSpan = trace.getSpan(context.active());. If the context is ever not propagated to the callback correctly, the attributes for the active span would contain noop or some other span which is not the receive span, thus future child spans will be scoped improperly.

I hope it is clear, and feel free to refactor the test so it better communicate it's intent. We can maybe create a new span in the callback and assert child-parent relationships, or we can just compare the active span id in the callback with the test span? I hope I don't miss anything there.

2. Still unsure about how/why this issue did not present itself earlier. The implementations for adding the MESSAGING_OPERATION attribute and the unit tests have not had any recent changes, and I am not yet sure about the correlation between the @aws-sdk/client-sqs version bump and this test failure.

To me the immediate suspect is this S3 create bucket which seems unrelated. I would add a breakpoint and trace the stack to follow it's roots.

Feel free to ping me in slack to research together.