opentelemetry-instrumentation-psycopg claims to work for async queries, but doesn't record time

[samuelcolvin]

This was orignally reported as pydantic/logfire#65 which has version details etc.

But in summary, using opentelemetry-instrumentation-psycopg="0.45b0" to instrument asyncio queries, doesn't work properly.

The cause is as follows:

opentelemetry-python-contrib/instrumentation/opentelemetry-instrumentation-psycopg/src/opentelemetry/instrumentation/psycopg/__init__.py

Lines 335 to 338 in 5116305

	async def execute(self, *args, **kwargs):
	return await _cursor_tracer.traced_execution(
	self, super().execute, *args, **kwargs
	)

calls

opentelemetry-python-contrib/instrumentation/opentelemetry-instrumentation-dbapi/src/opentelemetry/instrumentation/dbapi/__init__.py

Lines 472 to 475 in 5116305

	def execute(self, *args, **kwargs):
	return _cursor_tracer.traced_execution(
	self.__wrapped__, self.__wrapped__.execute, *args, **kwargs
	)

calls

opentelemetry-python-contrib/instrumentation/opentelemetry-instrumentation-dbapi/src/opentelemetry/instrumentation/dbapi/__init__.py

Lines 408 to 414 in 5116305

	def traced_execution(
	self,
	cursor,
	query_method: typing.Callable[..., typing.Any],
	*args: typing.Tuple[typing.Any, typing.Any],
	**kwargs: typing.Dict[typing.Any, typing.Any],
	):

which isn't designed to support an awaitable query_method, so it immediately returns a future, which gets awaited after the span has closed, hence zero time spans:

From Logfire, we see:

when we'd expect something similar to what's observed with sync calls:

I'm not clear why TracedCursorProxy is required rather than just using CursorTracer, but either way, I'd suggest implementing an async varient of traced_execution which tries to share as much logic as possible with the sync method.

If you agree, I'll try to create a PR for this over the next week or so.

[xrmx]

cc @federicobond

[federicobond]

Thanks for the ping @xrmx. Agree that this is a bug and your proposed solution sounds reasonable @samuelcolvin, happy to review your PR

[Kludex]

If someone can review this: #3067, and #3068... I'm happy to work on this, properly.

Also, knowing the reason for TracedCursorProxy would be nice.