ERROR [ddtrace.profiling.scheduler] [scheduler.py:81] - Unexpected error while exporting events. Please report this bug to https://github.com/DataDog/dd-trace-py/issues

[geoff-at-maplabs]

Summary of problem

Lots of errors and in Google Cloud Run logs indicating retry errors with the following:

ERROR [ddtrace.profiling.scheduler] [scheduler.py:81] [dd.service=core-api dd.env=production dd.version= dd.trace_id=0 dd.span_id=0] - Unexpected error while exporting events. Please report this bug to https://github.com/DataDog/dd-trace-py/issues

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

2.12.1

Which version of pip are you using?

root@dc856f549356:/app# pip --version
pip 24.0 from /usr/local/lib/python3.11/site-packages/pip (python 3.11)

Which libraries and their versions are you using?

Details of `pip freeze`

root@dc856f549356:/app# pip freeze
aiohttp==3.8.4
aiosignal==1.3.1
annotated-types==0.7.0
anyio==3.6.2
async-timeout==4.0.3
attrs==24.2.0
Brotli==1.1.0
cachetools==5.5.0
certifi==2023.5.7
cffi==1.17.1
charset-normalizer==3.3.2
click==8.1.3
coverage==7.6.1
cssselect2==0.7.0
datadog-api-client==2.12.0
dnspython==2.3.0
email-validator==2.0.0.post2
envkey==2.3.1
fastapi==0.100.1
fonttools==4.53.1
frozenlist==1.4.1
google-api-core==2.19.2
google-auth==2.19.1
google-cloud-core==2.4.1
google-cloud-pubsub==2.18.2
google-cloud-storage==2.10.0
google-cloud-tasks==2.16.3
google-crc32c==1.6.0
google-resumable-media==2.7.2
googleapis-common-protos==1.65.0
grpc-google-iam-v1==0.13.1
grpcio==1.66.1
grpcio-status==1.62.3
h11==0.14.0
html5lib==1.1
httpcore==0.17.1
httptools==0.5.0
httpx==0.24.1
idna==3.4
iniconfig==2.0.0
itsdangerous==2.1.2
Jinja2==3.1.2
MarkupSafe==2.1.2
motor==3.1.2
multidict==6.1.0
numpy==1.26.4
orjson==3.8.12
packaging==24.1
pandas==1.2.4
pillow==10.4.0
pluggy==1.5.0
proto-plus==1.24.0
protobuf==4.25.4
pyasn1==0.6.0
pyasn1_modules==0.4.0
pycparser==2.22
pydantic==2.1.1
pydantic_core==2.4.0
pydyf==0.10.0
pymongo==4.3.3
pyphen==0.16.0
pytest==8.3.3
pytest-asyncio==0.21.0
pytest-cov==4.1.0
pytest-mock==3.11.1
python-dateutil==2.8.2
python-dotenv==1.0.0
python-multipart==0.0.6
pytz==2024.1
PyYAML==6.0
requests==2.31.0
rsa==4.9
six==1.16.0
sniffio==1.3.0
starlette==0.27.0
tinycss2==1.3.0
tornado==6.4.1
typing_extensions==4.6.1
ujson==5.7.0
urllib3==1.26.20
uvicorn==0.22.0
uvloop==0.17.0
watchfiles==0.19.0
weasyprint==60.2
webencodings==0.5.1
websockets==11.0.3
yarl==1.11.1
zopfli==0.2.3

How can we reproduce your problem?

Not sure how to repro. We have a FastAPI app that is containerized and running in Google Cloud Run.

The following DD_ * env vars are set:

DD_LOGS_INJECTION=true
DD_PROFILING_ENABLED=true
DD_SERVICE=core-api
DD_SITE=datadoghq.com
DD_TRACE_ENABLED=true
DD_TRACE_TELEMETRY_ENABLED=false

What is the result that you get?

Details log output from Google Cloud Run logs:

ERROR 2024-09-11T03:28:05.821976Z Traceback (most recent call last): File "/dd_tracer/python/ddtrace/profiling/scheduler.py", line 77, in flush exp.export(events, start, self._last_export) File "/dd_tracer/python/ddtrace/profiling/exporter/http.py", line 263, in export self._upload(client, self.endpoint_path, body, headers) File "/dd_tracer/python/ddtrace/internal/utils/retry.py", line 49, in retry_wrapped raise exception File "/dd_tracer/python/ddtrace/internal/utils/retry.py", line 40, in retry_wrapped result = f(*args, **kwargs)
DEFAULT 2024-09-11T03:28:05.821980Z ^^^^^^^^^^^^^^^^^^
DEFAULT 2024-09-11T03:28:05.821985Z File "/dd_tracer/python/ddtrace/profiling/exporter/http.py", line 281, in _upload
DEFAULT 2024-09-11T03:28:05.821991Z raise RuntimeError("Server returned %d" % response.status)
DEFAULT 2024-09-11T03:28:06.887630Z RuntimeError: Server returned 502
DEFAULT 2024-09-11T03:30:38.218156Z 2024-09-11 03:30:38,216 ERROR [ddtrace.profiling.scheduler] [scheduler.py:81] [dd.service=core-api dd.env=production dd.version= dd.trace_id=0 dd.span_id=0] - Unexpected error while exporting events. Please report this bug to https://github.com/DataDog/dd-trace-py/issues
ERROR 2024-09-11T03:30:38.218221Z Traceback (most recent call last): File "/dd_tracer/python/ddtrace/profiling/scheduler.py", line 77, in flush exp.export(events, start, self._last_export) File "/dd_tracer/python/ddtrace/profiling/exporter/http.py", line 263, in export self._upload(client, self.endpoint_path, body, headers) File "/dd_tracer/python/ddtrace/internal/utils/retry.py", line 49, in retry_wrapped raise exception File "/dd_tracer/python/ddtrace/internal/utils/retry.py", line 40, in retry_wrapped result = f(*args, **kwargs)

What is the result that you expected?

We expect ddtrace to not pollute logs with errors and traces as this creates noise and logging (cost) overhead. More concerning is that this indicates we may not be getting the observability in DataDog that we expect/desire.

[shivaal-mako]

+1 I'm also seeing this

[shivaal-mako]

I ended up solving this for myself. For me, the problem was that I was not setting my DD_SITE correctly. Make sure it's pointed to your profile's site (e.g. us1.datadoghq.com, us3.datadoghq.com, us5.datadoghq.com etc) and also that you're not including any extra quotation marks around the URL.

[sanchda]

👋 @geoff-at-maplabs

Whoa! Sincere apologies for neglecting this one, it fell through the cracks. Were you able to resolve this issue? The fact that you're using GCR might change things a little bit, depending on your setup. Happy to help.

As for the log spamming, I agree that the profiler doesn't need to spam the logs with noise if it still can't connect to an endpoint after being unable to connect before.

[geoff-at-maplabs]

👋 @geoff-at-maplabs

Whoa! Sincere apologies for neglecting this one, it fell through the cracks. Were you able to resolve this issue? The fact that you're using GCR might change things a little bit, depending on your setup. Happy to help.

No worries @sanchda

We are running on GCR (Knatvie under the hood) and our app runs containerized with the following CMD in our Dockerfile:

CMD /app/datadog-init /dd_tracer/python/bin/ddtrace-run uvicorn main:app --host 0.0.0.0 --port ${APP_PORT}

as per suggestions in the DataDog docs (see https://docs.datadoghq.com/serverless/google_cloud_run)

As of now (Dec 20, 2024) we have not resolved this and still see this intermittently in our logs.

Traceback (most recent call last):
  File "/dd_tracer/python/ddtrace/profiling/scheduler.py", line 82, in flush
    exp.export(events, start, self._last_export)
  File "/dd_tracer/python/ddtrace/profiling/exporter/http.py", line 237, in export
    self._upload(client, self.endpoint_path, body, headers)
  File "/dd_tracer/python/ddtrace/internal/utils/retry.py", line 49, in retry_wrapped
    raise exception
  File "/dd_tracer/python/ddtrace/internal/utils/retry.py", line 40, in retry_wrapped
    result = f(*args, **kwargs)
  File "/dd_tracer/python/ddtrace/profiling/exporter/http.py", line 255, in _upload
    raise RuntimeError("Server returned %d" % response.status)
RuntimeError: Server returned 502

And incidence is roughly 1 per day:

Dec 20 14:03:34.640 billing-api Traceback (most recent call last): 
  File "/dd_tracer/python/ddtrace/profiling/scheduler.py", line 82, 
  in flush exp.export(events, start, self._last_export) 
  RuntimeError: Server returned 502
Dec 20 13:54:40.440 billing-api Traceback (most recent call last): 
  File "/dd_tracer/python/ddtrace/profiling/scheduler.py", line 82,
  in flush exp.export(events, start, self._last_export) 
  RuntimeError: Server returned 502
Dec 20 13:39:50.639 billing-api Traceback (most recent call last): 
  File "/dd_tracer/python/ddtrace/profiling/scheduler.py", line 82, 
  in flush exp.export(events, start, self._last_export) 
  RuntimeError: Server returned 502
Dec 20 12:22:31.640 billing-api Traceback (most recent call last): 
  File "/dd_tracer/python/ddtrace/profiling/scheduler.py", line 82, 
  in flush exp.export(events, start, self._last_export) 
  RuntimeError: Server returned 502
Dec 19 01:22:08.667 billing-api Traceback (most recent call last): 
  File "/dd_tracer/python/ddtrace/profiling/scheduler.py", line 78, 
  in flush exp.export(events, start, self._last_export) 
  RuntimeError: Server returned 502
Dec 18 00:18:28.582 billing-api Traceback (most recent call last): 
  File "/dd_tracer/python/ddtrace/profiling/scheduler.py", line 78, in flush exp.export(events, start, self._last_export) 
  RuntimeError: Server returned 502

[sanchda]

@geoff-at-maplabs thank you for the information. It might take a while for us to close the loop on this, since I'll need to put my head together with our serverless team.

It seems to me that there are two symptoms associated to this issue. I'm inclined to focus on solving the first category, but if what you really care about is the second category, then please let me know and I'll pivot.

1. The profiler is conspicuously mis-communicating with its intake component and hitting 502s. This causes profiling data to be dropped.
2. The profiler is way too chatty for an intermittent issue (I'd probably have to provide an option to silence HTTP transport errors in serverless environments altogether, since I can't propagate state competently in these environments to implement an error-only-once strategy).

For background information, or in case someone else needs to pick up this ticket, here's my thinking.

The way Datadog structures its GCR serverless offering is--as per our public docs--by stapling a trace agent to the user's serverless application. The SDK communicates with this trace agent, which proxies load to intake (i.e., the DD_SITE). Compared to traces, profiles are quite large--moreover, while we ordinarily retain data in the client for 60s and batch-flush, serverless configures the profiler to retain data for the duration of the serverless application and send it all at once. This is done to improve request-determinism, minimize overhead, and unify the experience for long- and short-duration serverless executions.

Receiving a 502 is... weird. It arises whenever the proxy (trace agent) correctly connects to intake, correctly receives and flushes the request to intake, correctly receives some kind of message in response, but then that message is not interpretable as a valid HTTP message. Also keep in mind that all of this is happening over TLS, and we'd have gotten a TLS-level rejection in the first part if this was something silly, like connecting to a non-HTTP server for horrible or hilarious reasons.

In my completely subjective personal experience, "usually" the 502 is an error in the transmission of a success response. In other words, everything worked, but the client just didn't get to hear the good news.

What makes this even weirder is that, by design, the success response is tiny. I forget whether we emit an empty body, a body consisting of the empty json object, or even just the letters "OK," but either way the transmission should be some small, compact deal.

Note to self: it'd be useful to investigate some time whether the response HTTP messages are typically received in a single TCP segment. Not for this issue though (I hope).