FastApi auto-instrumentation send extra spans for a single API execution

[RunzhongHuang]

Hi open-telemetry community,

I have a python project with fastapi auto-instrumentation which export the spans to zipkin server, and I have a simple "GET" API which returns a "hello". But I notice it generates 3 spans instead of 1.

As you can see, the top one is related to the request I send out. But the other 2 child spans, I am not sure why they are there.

Describe your environment
python = 3.8
opentelemetry-api = 1.7.1
opentelemetry-sdk = 1.7.1
opentelemetry-exporter-zipkin = 1.7.1
opentelemetry-instrumentation-fastapi = 0.26b1
fastapi = 0.70.0
uvicorn = 0.15.0

Steps to reproduce

from opentelemetry import trace
from opentelemetry.exporter.zipkin.json import ZipkinExporter
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.resources import Resource
from opentelemetry.sdk.trace.export import SimpleSpanProcessor
from fastapi import FastAPI
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
import uvicorn

app = FastAPI()

tracer = trace.get_tracer(__name__)

zipkin_exporter = ZipkinExporter(
    endpoint="https://bolt-msl-zipkin-server.eks-dev-us-east-1.container.spglobal.com:30443/api/v2/spans",
)
span_processor = SimpleSpanProcessor(zipkin_exporter)
trace_provider = TracerProvider(resource=Resource.create({"service.name": "open-telemetry-test"}))
trace_provider.add_span_processor(span_processor)

@app.get('/opentelemetry-fastapi')
def about():
   return "hello"


FastAPIInstrumentor.instrument_app(app,
                                   tracer_provider=trace_provider)

if __name__ == "__main__":
    uvicorn.run(app, host="0.0.0.0", port=8000)

Here is the REST request I made:

curl --location --request GET 'http://localhost:8000/opentelemetry-fastapi'

Here is the JSON span metadata:

[{
	"traceId": "7e5511d0c28934bf480bc7f28ba2d34d",
	"parentId": "76122e06995e41b6",
	"id": "a920c88a2a64c8e2",
	"name": "/opentelemetry-fastapi http send",
	"timestamp": 1639091853270289,
	"duration": 1002,
	"localEndpoint": {
		"serviceName": "open-telemetry-test"
	},
	"tags": {
		"otel.library.name": "opentelemetry.instrumentation.asgi",
		"otel.library.version": "0.26b1",
		"service.name": "open-telemetry-test",
		"telemetry.sdk.language": "python",
		"telemetry.sdk.name": "opentelemetry",
		"telemetry.sdk.version": "1.7.1",
		"type": "http.response.body"
	},
	"debug": true
}, {
	"traceId": "7e5511d0c28934bf480bc7f28ba2d34d",
	"id": "76122e06995e41b6",
	"kind": "SERVER",
	"name": "/opentelemetry-fastapi",
	"timestamp": 1639091853034614,
	"duration": 289682,
	"localEndpoint": {
		"serviceName": "open-telemetry-test"
	},
	"tags": {
		"correlation-id": "111222333444555",
		"http.flavor": "1.1",
		"http.host": "127.0.0.1:8000",
		"http.method": "GET",
		"http.route": "/opentelemetry-fastapi",
		"http.scheme": "http",
		"http.server_name": "localhost:8000",
		"http.status_code": "200",
		"http.target": "/opentelemetry-fastapi",
		"http.url": "http://127.0.0.1:8000/opentelemetry-fastapi",
		"http.user_agent": "PostmanRuntime/7.28.4",
		"net.host.port": "8000",
		"net.peer.ip": "127.0.0.1",
		"net.peer.port": "55402",
		"otel.library.name": "opentelemetry.instrumentation.asgi",
		"otel.library.version": "0.26b1",
		"region": "us-east-1",
		"service.name": "open-telemetry-test",
		"telemetry.sdk.language": "python",
		"telemetry.sdk.name": "opentelemetry",
		"telemetry.sdk.version": "1.7.1"
	},
	"debug": true
}, {
	"traceId": "7e5511d0c28934bf480bc7f28ba2d34d",
	"parentId": "76122e06995e41b6",
	"id": "edd83d58575f0811",
	"name": "/opentelemetry-fastapi http send",
	"timestamp": 1639091853053617,
	"localEndpoint": {
		"serviceName": "open-telemetry-test"
	},
	"tags": {
		"http.status_code": "200",
		"otel.library.name": "opentelemetry.instrumentation.asgi",
		"otel.library.version": "0.26b1",
		"service.name": "open-telemetry-test",
		"telemetry.sdk.language": "python",
		"telemetry.sdk.name": "opentelemetry",
		"telemetry.sdk.version": "1.7.1",
		"type": "http.response.start"
	},
	"debug": true
}]

What is the expected behavior?
Exactly one span related to the API get executed.

What is the actual behavior?
Besides the span relates to the API got executed, there are 2 extra spans are generated.

Additional context

I am suspecting this is related to the ASGI interfaces since the extra span has "send" in it which related to sending response back. But shouldn't it be a single "send" instead two?

I feel like there could some missing link regarding certain concept. I am looking forward to hearing from your suggestions.

Thanks for your time!

[lzchen]

Duplicate of open-telemetry/opentelemetry-python-contrib#831