Skip to content

breakpoints/debug printing for Django ASGI investigation #3164

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

Closed

Conversation

szokeasaurusrex
Copy link
Member

@szokeasaurusrex szokeasaurusrex commented Jun 12, 2024

The problem (see #3142) is as follows: We expect there to be three events in the test, but right now (in master), the test verifies only that we have two events, with the transaction missing. So, we want to find out what happens with the transaction.

The lack of transaction seems unique to the testing environment – when I tried to reproduce with a similar setup outside of a testing environment, I saw transactions as expected in Sentry. Therefore, it appears that either no transaction is created during testing, or we somehow fail to capture the transaction in the TestTransport that we use for the capture_events fixture.

I have tried placing breakpoints in many different places, but have still struggled to figure out the root cause for the strange behavior. In this PR, I have included two breakpoints that cause unexpected behavior. The first breakpoint we have is one in the __exit__ of a span; if the code is run as is with tox -e py3.12-django-latest -- tests/integrations/django/asgi/test_asgi.py::test_trace_from_headers_if_performance_enabled, we hit that breakpoint three times (perhaps, because we have spans as well as a transaction). Then, we will end up inside the second breakpoint in capture_event. Since this breakpoint is inside an if is_transaction block, we know that we are about to capture the transaction. If we step through the transport capture_envelope call, we see that we correctly add the transaction event to the events list. However, when we continue from this last breakpoint, the test fails with an asyncio TimeoutError.

If we comment out the breakpoint in Span.__exit__, however, we do not hit the breakpoint in capture_event at all, suggesting that for whatever reason the transaction does not get captured in this case. We end up failing with the assertion error, since there are only two, rather than three, events in the test. No asyncio TimeoutError in this case.

I am not really sure yet what to make of all this strange behavior, but I guess asyncio somehow prevents the transaction from being captured in our tests

@szokeasaurusrex szokeasaurusrex self-assigned this Jun 12, 2024
@szokeasaurusrex
Copy link
Member Author

I noticed the following in the test failure logs when running with both breakpoints commented out:

Task was destroyed but it is pending!
task: <Task cancelling name='Task-2' coro=<patch_django_asgi_handler_impl.<locals>.sentry_patched_asgi_handler() running at /Users/dszoke/Development/SDK/sentry-python/sentry_sdk/integrations/django/asgi.py:101> wait_for=<Task cancelling name='Task-4' coro=<ASGIHandler.listen_for_disconnect() running at /Users/dszoke/Development/SDK/sentry-python/.tox/py3.12-django-latest/lib/python3.12/site-packages/django/core/handlers/asgi.py:243> wait_for=<Future cancelled> cb=[Task.task_wakeup()]>>
Exception ignored in: <coroutine object patch_django_asgi_handler_impl.<locals>.sentry_patched_asgi_handler at 0x10454c150>
Traceback (most recent call last):
  File "/Users/dszoke/Development/SDK/sentry-python/sentry_sdk/integrations/django/asgi.py", line 101, in sentry_patched_asgi_handler
  File "/Users/dszoke/Development/SDK/sentry-python/sentry_sdk/integrations/asgi.py", line 144, in _run_asgi3
  File "/Users/dszoke/Development/SDK/sentry-python/sentry_sdk/integrations/asgi.py", line 163, in _run_app
  File "/Users/dszoke/.pyenv/versions/3.12.0/lib/python3.12/contextlib.py", line 155, in __exit__
  File "/Users/dszoke/Development/SDK/sentry-python/sentry_sdk/scope.py", line 1627, in isolation_scope
ValueError: <Token var=<ContextVar name='current_scope' default=None at 0x10237f4c0> at 0x104406240> was created in a different Context
Task was destroyed but it is pending!
task: <Task cancelling name='Task-4' coro=<ASGIHandler.listen_for_disconnect() running at /Users/dszoke/Development/SDK/sentry-python/.tox/py3.12-django-latest/lib/python3.12/site-packages/django/core/handlers/asgi.py:243> wait_for=<Future cancelled> cb=[Task.task_wakeup()]>

So, I guess the asyncio task is somehow getting cancelled before we can capture the transaction.

@antonpirker
Copy link
Member

Your guess was right @szokeasaurusrex the problem was simply that we need to wait() for the ASGI application to be finished to be able to check for transactions (otherwise the task is killed before the transaction could be sent out)

See: #3180

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants