Running ddtrace-run in debug mode causes CORS errors on the application

[umutkacar]

Which version of dd-trace-py are you using?

1.5.1

Which version of pip are you using?

22.0.4

Which version of the libraries are you using?

Adyen==4.0.0 amqp==5.1.1 aniso8601==7.0.0 anyio==3.6.1 asgiref==3.5.2 astroid==2.12.5 async-timeout==4.0.2 attrs==22.1.0 Authlib==1.0.1 authorizenet==1.1.4 azure-common==1.1.28 azure-core==1.25.0 azure-storage-blob==12.13.1 azure-storage-common==2.1.0 Babel==2.10.3 bcrypt==4.0.0 beautifulsoup4==4.7.1 beautifultable==0.7.0 before-after==1.0.1 billiard==3.6.4.0 black==22.6.0 boto3==1.24.61 botocore==1.27.61 braintree==4.16.0 Brotli==1.0.9 bytecode==0.13.0 cachetools==5.2.0 cattrs==22.2.0 celery==5.2.7 certifi==2022.9.24 cffi==1.15.1 cfgv==3.3.1 charset-normalizer==2.1.1 click==8.1.3 click-didyoumean==0.3.0 click-plugins==1.1.1 click-repl==0.2.0 codecov==2.1.12 colorama==0.4.5 coverage==6.4.4 cryptography==37.0.4 cssselect2==0.6.0 datadog==0.44.0 ddsketch==2.0.4 ddtrace==1.5.1 Deprecated==1.2.13 dill==0.3.5.1 distlib==0.3.6 dj-database-url==0.5.0 dj-email-url==1.0.5 Django==3.2.16 django-appconf==1.0.5 django-cache-url==3.4.2 django-celery-beat==2.3.0 django-countries==7.3.2 django-debug-toolbar==3.6.0 django-debug-toolbar-request-history==0.1.4 django-extensions==3.2.0 django-filter==22.1 django-graphiql-debug-toolbar==0.2.0 django-js-asset==2.0.0 django-measurement==3.2.4 django-mptt==0.13.4 django-phonenumber-field==6.4.0 django-prices==2.2.0 django-prices-openexchangerates==1.1.0 django-prices-vatlayer==1.1.0 django-redis==5.2.0 django-storages==1.13.1 django-stubs==1.8.0 django-stubs-ext==0.5.0 django-timezone-field==5.0 django-versatileimagefield==2.2 draftjs-sanitizer==1.0.0 enmerkar==0.7.1 envier==0.4.0 et-xmlfile==1.1.0 exceptiongroup==1.0.0rc9 execnet==1.9.0 Faker==14.1.0 fakeredis==1.9.0 filelock==3.8.0 flake8==4.0.1 fonttools==4.37.1 freezegun==1.2.2 google-api-core==2.8.2 google-auth==2.11.0 google-cloud-core==2.3.2 google-cloud-pubsub==2.13.6 google-cloud-storage==2.5.0 google-crc32c==1.3.0 google-i18n-address==2.5.2 google-measurement-protocol==1.1.0 google-resumable-media==2.3.3 googleapis-common-protos==1.56.4 graphene==2.1.9 graphene-django==2.15.0 graphql-core==2.3.2 graphql-relay==2.0.1 grpc-google-iam-v1==0.12.4 grpcio==1.48.0 grpcio-status==1.48.0 gunicorn==20.1.0 h11==0.13.0 html-to-draftjs==1.0.1 html2text==2020.1.16 html5lib==1.1 httptools==0.4.0 identify==2.5.3 idna==3.4 importlib-metadata==4.12.0 iniconfig==1.1.1 ipaddress==1.0.23 isodate==0.6.1 isort==5.10.1 jaeger-client==4.8.0 Jinja2==3.1.2 jmespath==1.0.1 jsonfield==3.1.0 jsonschema==4.16.0 kombu==5.2.4 lazy-object-proxy==1.7.1 lxml==4.9.1 Markdown==3.4.1 MarkupSafe==2.1.1 maxminddb==2.2.0 mccabe==0.6.1 measurement==3.2.0 micawber==0.5.4 mock==1.0.1 mpmath==1.2.1 msrest==0.7.1 multidict==6.0.2 mypy==0.971 mypy-extensions==0.4.3 nodeenv==1.7.0 oauthlib==3.2.1 openpyxl==3.0.10 opentracing==2.4.0 packaging==21.3 pathspec==0.9.0 petl==1.7.11 phonenumberslite==8.12.54 Pillow==9.2.0 platformdirs==2.5.2 pluggy==1.0.0 posuto==2022.8.0 pre-commit==2.20.0 prices==1.1.0 promise==2.3 prompt-toolkit==3.0.30 proto-plus==1.22.0 protobuf==4.21.7 psycopg2==2.9.3 py==1.11.0 pyasn1==0.4.8 pyasn1-modules==0.2.8 pybars3==0.9.7 pycodestyle==2.8.0 pycparser==2.21 pydocstyle==6.1.1 pydyf==0.2.0 pyflakes==2.4.0 PyJWT==2.4.0 pylint==2.15.0 pylint-celery==0.3 pylint-django==2.5.3 pylint-plugin-utils==0.7 PyMeta3==0.5.1 pyparsing==3.0.9 pyphen==0.12.0 pyrsistent==0.18.1 pytest==7.1.2 pytest-celery==0.0.0 pytest-cov==3.0.0 pytest-django==4.5.2 pytest-django-queries==1.2.0 pytest-forked==1.4.0 pytest-mock==3.8.2 pytest-recording==0.12.1 pytest-socket==0.5.1 pytest-xdist==2.5.0 python-crontab==2.6.0 python-dateutil==2.8.2 python-dotenv==0.20.0 python-http-client==3.3.7 python-json-logger==2.0.4 python-magic==0.4.27 pytimeparse==1.1.8 pytz==2022.2.1 pywatchman==1.4.1 PyXB==1.2.5 PyYAML==6.0 razorpay==1.3.0 redis==4.3.4 requests==2.28.1 requests-oauthlib==1.3.1 rsa==4.9 Rx==1.6.1 s3transfer==0.6.0 sendgrid==6.9.7 sentry-sdk==1.9.5 singledispatch==3.7.0 six==1.16.0 sniffio==1.2.0 snowballstemmer==2.2.0 sortedcontainers==2.4.0 soupsieve==2.3.2.post1 sqlparse==0.4.2 starkbank-ecdsa==2.0.3 stripe==3.5.0 sympy==1.11 tenacity==8.1.0 text-unidecode==1.3 threadloop==1.0.2 thrift==0.16.0 tinycss2==1.1.1 toml==0.10.2 tomli==2.0.1 tomlkit==0.11.4 tornado==6.2 tox==3.25.1 types-certifi==2021.10.8.3 types-freezegun==1.1.10 types-pkg-resources==0.1.3 types-python-dateutil==2.8.19 types-pytz==2022.2.1.0 types-redis==4.3.18 types-requests==2.28.9 types-six==1.16.19 types-urllib3==1.26.23 typing_extensions==4.4.0 tzdata==2022.2 urllib3==1.26.12 uvicorn==0.17.6 uvloop==0.16.0 vcrpy==4.2.0 vine==5.0.0 virtualenv==20.16.3 watchgod==0.8.2 wcwidth==0.2.5 weasyprint==56.1 webencodings==0.5.1 websockets==10.3 wrapt==1.14.1 xmltodict==0.13.0 yarl==1.8.1 zipp==3.8.1 zopfli==0.2.1

How can we reproduce your problem?

Setup Saleor (https://github.com/saleor/saleor) and Saleor Dashboard (https://github.com/saleor/saleor-dashboard) with the following versions: (dashboard v3.7.8 & core v3.7.23), and execute them with ddtrace-run with the -d flag, or DD_TRACE_DEBUG=true on a Kubernetes cluster with Datadog agents are in place and running. List the products via Saleor Dashboard, and see the CORS errors on the browser console.

The CORS errors go away when you disable the debug mode by setting DD_TRACE_DEBUG=false.

What is the result that you get?

Some responses from the server lacked the access-control-allow-origin headers, and that caused CORS errors.

What is the result that you expected?

I expected that the ddtrace-run running in debug mode wouldn't effect the running application's behavior or cause any malfunctions.

CC: @ogunheper

[majorgreys]

Can you include examples of the CORS errors in the browser console?

[umutkacar]

@majorgreys I got these screenshots left from the incident time. Some responses for /graphql/ missed the access-control-allow-origin header, while the majority of others have it.

[majorgreys]

@umutkacar And to confirm, this problem does not occur if you do not use ddtrace in a deploy of this app?

[umutkacar]

@majorgreys That's right. The problem also does not occur when ddtrace is used, but not in debug mode.

[Yun-Kim]

Hi @umutkacar, do you see any related error logs/spans or tracebacks raised in your Datadog application? If so, could you include them here?

[umutkacar]

Hi @Yun-Kim,

There are lots of these errors accompanied by the 500 status code, from when the issue was present;

django.core.exceptions.SynchronousOnlyOperation: You cannot call this from an async context - use a thread or sync_to_async.
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/ddtrace/contrib/asgi/middleware.py", line 198, in __call__
    return await self.app(scope, receive, wrapped_send)
  File "/usr/local/lib/python3.9/site-packages/sentry_sdk/integrations/django/asgi.py", line 39, in sentry_patched_asgi_handler
    return await middleware(scope, receive, send)
  File "/usr/local/lib/python3.9/site-packages/sentry_sdk/integrations/asgi.py", line 126, in _run_asgi3
    return await self._run_app(scope, lambda: self.app(scope, receive, send))
  File "/usr/local/lib/python3.9/site-packages/sentry_sdk/integrations/asgi.py", line 176, in _run_app
    raise exc from None
  File "/usr/local/lib/python3.9/site-packages/sentry_sdk/integrations/asgi.py", line 171, in _run_app
    return await callback()
  File "/usr/local/lib/python3.9/site-packages/django/core/handlers/asgi.py", line 161, in __call__
    response = await self.get_response_async(request)
  File "/usr/local/lib/python3.9/site-packages/sentry_sdk/integrations/django/asgi.py", line 51, in sentry_patched_get_response_async
    return await old_get_response_async(self, request)
  File "/usr/local/lib/python3.9/site-packages/ddtrace/contrib/django/_asgi.py", line 35, in traced_get_response_async
    _after_request_tags(pin, span, request, response)
  File "/usr/local/lib/python3.9/site-packages/ddtrace/contrib/django/utils.py", line 307, in _after_request_tags
    log.debug("Error retrieving authentication information for user %r", user, exc_info=True)
  File "/usr/local/lib/python3.9/logging/__init__.py", line 1434, in debug
    self._log(DEBUG, msg, args, **kwargs)
  File "/usr/local/lib/python3.9/logging/__init__.py", line 1587, in _log
    record = self.makeRecord(self.name, level, fn, lno, msg, args,
  File "/usr/local/lib/python3.9/site-packages/ddtrace/contrib/logging/patch.py", line 61, in _w_makeRecord
    record = func(*args, **kwargs)
  File "/usr/local/lib/python3.9/logging/__init__.py", line 1556, in makeRecord
    rv = _logRecordFactory(name, level, fn, lno, msg, args, exc_info, func,
  File "/usr/local/lib/python3.9/logging/__init__.py", line 308, in __init__
    if (args and len(args) == 1 and isinstance(args[0], collections.abc.Mapping)
  File "/usr/local/lib/python3.9/abc.py", line 119, in __instancecheck__
    return _abc_instancecheck(cls, instance)
  File "/usr/local/lib/python3.9/site-packages/django/utils/functional.py", line 246, in inner
    self._setup()
  File "/usr/local/lib/python3.9/site-packages/django/utils/functional.py", line 382, in _setup
    self._wrapped = self._setupfunc()
  File "/app/saleor/graphql/context.py", line 70, in user
    return get_user(request) or AnonymousUser()
  File "/app/saleor/graphql/context.py", line 60, in get_user
    request._cached_user = cast(UserType, authenticate(request=request))
  File "/usr/local/lib/python3.9/site-packages/django/views/decorators/debug.py", line 42, in sensitive_variables_wrapper
    return func(*func_args, **func_kwargs)
django.core.exceptions.SynchronousOnlyOperation: You cannot call this from an async context - use a thread or sync_to_async.

And they went away after I set DD_TRACE_DEBUG=false.

[brettlangdon]

@umutkacar thanks, this is actually really helpful!

It seems we have a debug log that will log a repr of the current Django user, but resolving/casting that user instance is performing a sync operation from an async context?

It would also make sense why this goes away when you disable debug logging.

This is the offending line: https://github.com/DataDog/dd-trace-py/blob/1b577cc7832fa14b443a3254ae4ed45141c40257/ddtrace/contrib/django/utils.py#L308

It doesn't actually raise the exception until the logging module tries to repr user, which only occurs when debug logging is enabled.

When you disable debug logging do you properly get user information associated with tags? (e.g. django.user.is_authenticated, django.user.id, django.user.name ?)

I am wondering if while trying to access this data and set these tags we are actually getting the django.core.exceptions.SynchronousOnlyOperation?

If it never can be successful accessing the user this way/at this time, then I wonder if adding a config switch to disable trying to collect user data is the best approach, at least short term? what do you think?

[mabdinur]

Hey @umutkacar,

Thanks for flagging this issue. I just opened a PR to fix this issue.