Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

aiopg instrumentation creating nested traces #336

Closed
cdvv7788 opened this issue Feb 15, 2021 · 4 comments · Fixed by #381
Closed

aiopg instrumentation creating nested traces #336

cdvv7788 opened this issue Feb 15, 2021 · 4 comments · Fixed by #381
Labels
bug Something isn't working

Comments

@cdvv7788
Copy link
Contributor

Describe your environment
Python 3.6.12
Macos 11.1
opentelemetry-python-contrib: Tried released version, as well as main.
aiohttp==3.7.3
aiopg==1.1.0

Describe any aspect of your environment relevant to the problem, including your Python version, platform, version numbers of installed dependencies, information about your cloud hosting provider, etc. If you're reporting a problem with a specific version of a library in this repo, please check whether the problem has been fixed on main.

Steps to reproduce
I am trying the aiopg instrumentation. I am using it along aiohttp. This may be an usage issue, but I have created a minimal example in here (Just install requirements, run, and visit localhost:4000...you will need a postgres database named test and jaeger running somewhere).
The trace will keep growing with every request, nesting new traces every time:
image

What is the expected behavior?
Every connection has a single trace (no nesting)

What is the actual behavior?
Every time a request is made, a new trace is nested and sends the whole stack to jaeger

Notes
This may be a bad usage issue. If that is the case, please let me know what may be causing it and how to use this properly.

@cdvv7788 cdvv7788 added the bug Something isn't working label Feb 15, 2021
@cdvv7788
Copy link
Contributor Author

@sartx I saw you worked on this implementation (open-telemetry/opentelemetry-python#801). Can you please check this issue?
Using pdb it is entering traced_execution at least 3 times in the sample (1 for a single span, 2 nested). If I keep refreshing, the nesting keeps growing. Checking with opentelemetry.trace.get_current_span() it is indeed getting a SELECT span (Instead of Default, which is what I was expecting) and putting the next one inside.

@sartx
Copy link
Contributor

sartx commented Mar 10, 2021

Hello, I have an idea why it is broken.

In previous versions of opentelemetry start_as_current_span had argument parent. If it had no value then DEFAULT span was used as parent. In current version if context was not given as argument in this function RUNTIME_CONTEXT is used as context. As far as I understand it is a global variable.
First request uses RUNTIME_CONTEXT as parent span and addes own new context to RUNTIME_CONTEXT.
While first request is not ended the second one comes to the application and it uses RUNTIME_CONTEXT as parent to, but there is still the context from the first request. Old span is closing only after all child spans were closed.

If you want to check it you may try to call new request after previous is ended.
Using contextvar variable for context probably will fix this issue.

@cdvv7788
Copy link
Contributor Author

Thanks for jumping in. The requests are not running in parallel, they are sequential. Some reference is being kept around in the process, and it will keep nesting.

@cdvv7788
Copy link
Contributor Author

cdvv7788 commented Apr 5, 2021

I updated the repository where I reproduced the bug and it has indeed gone away using the latest version. Thanks!
image

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
2 participants