[Regression] urllib3 downstream instrumentation not getting suppressed (with requests, boto3 upstream)

[NathanielRN]

Description

I thought that in #563 I had stopped calls to downstream Python packages from getting instrumented after instrumenting the AWS SDK.

However, my colleague @yimipeng discovered that DynamoDB calls still have HTTP traces from urllib3 when he instruments botocore.

For example, when using OTel Python instrumentation he sees this service map:

It's not until he adds this line:

ENV OTEL_PYTHON_DISABLED_INSTRUMENTATIONS=urllib3

that he sees the downstream urllib3 traces disappear:

His sample app which is already on GitHub is simple too:

flask
boto3
opentelemetry-distro[otlp]>=0.24b0 # This should take the latest 0.28b1, right?
opentelemetry-sdk-extension-aws~=2.0
opentelemetry-propagator-aws-xray~=1.0

FROM public.ecr.aws/amazonlinux/amazonlinux:latest
RUN yum install python3.7 -y && curl -O https://bootstrap.pypa.io/get-pip.py && python3 get-pip.py && yum update -y
COPY . /app
WORKDIR /app
RUN pip3 install -r requirements.txt
RUN opentelemetry-bootstrap --action=install
ENV OTEL_RESOURCE_ATTRIBUTES='service.name=movies_app'
CMD OTEL_PROPAGATORS=xray OTEL_PYTHON_ID_GENERATOR=xray opentelemetry-instrument python3 app.py
EXPOSE 8080

In #563 I showed my changes fix this for S3. I wonder if it's possible it's different for DynamoDB? Or if anything else changed?

[NathanielRN]

Actually, I just tried this with an app that has requests and flask instrumentation. I get 2 HTTP GET traces because the urllib3 instrumentation is not being suppressed:

InstrumentationLibrarySpans #0
InstrumentationLibraryMetrics SchemaURL:
InstrumentationLibrary opentelemetry.instrumentation.urllib3 0.28b1
Span #0
    Trace ID       : 621d271f2c19cd88758b0a9523dd9b4d
    Parent ID      : 1606c9c162204066
    ID             : 251eb36c77f30a1a
    Name           : HTTP GET
    Kind           : SPAN_KIND_CLIENT
    Start time     : 2022-02-28 19:48:47.561919 +0000 UTC
    End time       : 2022-02-28 19:48:48.696018 +0000 UTC
    Status code    : STATUS_CODE_UNSET
    Status message :
Attributes:
     -> http.method: STRING(GET)
     -> http.url: STRING(https://aws.amazon.com/)

     -> http.status_code: INT(200)
InstrumentationLibrarySpans #1
InstrumentationLibraryMetrics SchemaURL:
InstrumentationLibrary opentelemetry.instrumentation.requests 0.28b1
Span #0
    Trace ID       : 621d271f2c19cd88758b0a9523dd9b4d
    Parent ID      : 14fd90f7035c58ba
    ID             : 1606c9c162204066
    Name           : HTTP GET
    Kind           : SPAN_KIND_CLIENT
    Start time     : 2022-02-28 19:48:47.557981 +0000 UTC
    End time       : 2022-02-28 19:48:48.70949 +0000 UTC
    Status code    : STATUS_CODE_UNSET
    Status message :
Attributes:
     -> http.method: STRING(GET)
     -> http.url: STRING(https://aws.amazon.com/)

     -> http.status_code: INT(200)
InstrumentationLibrarySpans #2
InstrumentationLibraryMetrics SchemaURL:
InstrumentationLibrary opentelemetry.instrumentation.flask 0.28b1
Span #0
    Trace ID       : 621d271f2c19cd88758b0a9523dd9b4d
    Parent ID      :
    ID             : 14fd90f7035c58ba
    Name           : /outgoing-http-call
    Kind           : SPAN_KIND_SERVER
    Start time     : 2022-02-28 19:48:47.543381 +0000 UTC
    End time       : 2022-02-28 19:48:48.714302 +0000 UTC
    Status code    : STATUS_CODE_UNSET
    Status message :

Not sure if requests by default suppresses downstream calls, but if it does it would seem that urllib3 is not getting suppressed?

[NathanielRN]

Another update. This bug only happens with AUTO-instrumented applications. I tested using our Sample OTel Python apps which has Auto and Manual instrumentation.

Maybe auto-instrumentation is instrumenting libraries twice?

When I use manual instrumentation (modified to use the Console Exporter):

span_processor = BatchSpanProcessor(ConsoleSpanExporter())
trace.set_tracer_provider(
    TracerProvider(
        active_span_processor=span_processor,
        id_generator=AwsXRayIdGenerator(),
    )
)

$ cd integration-test-apps/manual-instrumentation/flask
$ LISTEN_ADDRESS=0.0.0.0:8080 \
OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4317 \
OTEL_PROPAGATORS=xray \
OTEL_PYTHON_ID_GENERATOR=xray \
OTEL_SERVICE_NAME=my-manual-app \
python3 application.py

I get this output (only 2 spans):

{
    "name": "HTTP GET",
    "context": {
        "trace_id": "0x623b54d1f922b3aabd8dab9c00c9a51c",
        "span_id": "0xd43f2c739e53c14d",
        "trace_state": "[]"
    },
    "kind": "SpanKind.CLIENT",
    "parent_id": "0xe4b992f8ba6c667b",
    "start_time": "2022-03-23T17:11:45.147457Z",
    "end_time": "2022-03-23T17:11:45.253182Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.url": "https://aws.amazon.com/",
        "http.status_code": 200
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.9.1",
        "service.name": "my-manual-app"
    }
}
{
    "name": "/outgoing-http-call",
    "context": {
        "trace_id": "0x623b54d1f922b3aabd8dab9c00c9a51c",
        "span_id": "0xe4b992f8ba6c667b",
        "trace_state": "[]"
    },
    "kind": "SpanKind.SERVER",
    "parent_id": null,
    "start_time": "2022-03-23T17:11:45.144532Z",
    "end_time": "2022-03-23T17:11:45.256085Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.server_name": "0.0.0.0",
        "http.scheme": "http",
        "net.host.port": 8080,
        "http.host": "localhost:8080",
        "http.target": "/outgoing-http-call",
        "net.peer.ip": "127.0.0.1",
        "http.user_agent": "curl/7.64.1",
        "net.peer.port": 53701,
        "http.flavor": "1.1",
        "http.route": "/outgoing-http-call",
        "http.status_code": 200
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.9.1",
        "service.name": "my-manual-app"
    }
}

When I run the auto-insturmented application:

$ cd integration-test-apps/auto-instrumentation/flask
$ LISTEN_ADDRESS=0.0.0.0:8080 \
OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4317 \
OTEL_PROPAGATORS=xray \
OTEL_PYTHON_ID_GENERATOR=xray \
OTEL_SERVICE_NAME=my-auto-app
OTEL_TRACES_EXPORTER=console \
opentelemetry-instrument python3 application.py

I get 3 spans:

{
    "name": "HTTP GET",
    "context": {
        "trace_id": "0x623b542733ea87549f12c0dc82ca3ec2",
        "span_id": "0xa1be4613859aebe0",
        "trace_state": "[]"
    },
    "kind": "SpanKind.CLIENT",
    "parent_id": "0xf1a865664700344a",
    "start_time": "2022-03-23T17:08:55.780180Z",
    "end_time": "2022-03-23T17:08:55.882605Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.url": "https://aws.amazon.com/",
        "http.status_code": 200
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.9.1",
        "service.name": "my-auto-app",
        "telemetry.auto.version": "0.28b1"
    }
}
{
    "name": "HTTP GET",
    "context": {
        "trace_id": "0x623b542733ea87549f12c0dc82ca3ec2",
        "span_id": "0xf1a865664700344a",
        "trace_state": "[]"
    },
    "kind": "SpanKind.CLIENT",
    "parent_id": "0x5215b753e29547d1",
    "start_time": "2022-03-23T17:08:55.766490Z",
    "end_time": "2022-03-23T17:08:55.889985Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.url": "https://aws.amazon.com/",
        "http.status_code": 200
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.9.1",
        "service.name": "my-auto-app",
        "telemetry.auto.version": "0.28b1"
    }
}
{
    "name": "/outgoing-http-call",
    "context": {
        "trace_id": "0x623b542733ea87549f12c0dc82ca3ec2",
        "span_id": "0x5215b753e29547d1",
        "trace_state": "[]"
    },
    "kind": "SpanKind.SERVER",
    "parent_id": null,
    "start_time": "2022-03-23T17:08:55.764942Z",
    "end_time": "2022-03-23T17:08:55.892768Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.server_name": "0.0.0.0",
        "http.scheme": "http",
        "net.host.port": 8080,
        "http.host": "localhost:8080",
        "http.target": "/outgoing-http-call",
        "net.peer.ip": "127.0.0.1",
        "http.user_agent": "curl/7.64.1",
        "net.peer.port": 53348,
        "http.flavor": "1.1",
        "http.route": "/outgoing-http-call",
        "http.status_code": 200
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.9.1",
        "service.name": "my-auto-app",
        "telemetry.auto.version": "0.28b1"
    }
}