DataDog / dd-trace-py

Datadog Python APM Client
https://ddtrace.readthedocs.io/
Other
505 stars 396 forks source link

ImportError cannot import name '_build_git_packfiles_with_details' from 'ddtrace.ext.git' #8001

Open pmourlanne opened 6 months ago

pmourlanne commented 6 months ago

Summary of problem

On start-up, Sentry picks up the following error: ImportError: cannot import name '_build_git_packfiles_with_details' from 'ddtrace.ext.git'. We indeed don't see any traces in Datadog following this error.

The final error is AttributeError: module 'our-project-name' has no attribute 'logging'.

This issue appeared once we upgraded to dd-trace-py 2.4.0. I suspect https://github.com/DataDog/dd-trace-py/pull/7532 to be the culprit. I also don't understand why internal imports about ci visibility are run in our live environments.

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

2.4.0

Which version of pip are you using?

pip 23.3.2

Which libraries and their versions are you using?

`pip freeze` $ pip freeze amqp==5.1.1 analytics-python==1.2.9 argon2-cffi==23.1.0 argon2-cffi-bindings==21.2.0 asgiref==3.7.2 asttokens==2.2.1 attrs==23.1.0 awscli==1.29.85 backcall==0.2.0 billiard==3.6.4.0 boto3==1.28.80 botocore==1.31.85 bytecode==0.14.2 cached-property==1.5.2 cachetools==5.3.1 cattrs==23.1.2 celery==5.2.7 certifi==2023.7.22 cffi==1.15.1 charset-normalizer==3.2.0 click==8.1.3 click-didyoumean==0.3.0 click-plugins==1.1.1 click-repl==0.3.0 colorama==0.4.4 cryptography==41.0.7 datadog-api-client==1.12 ddsketch==2.0.4 ddtrace==2.4.0 decorator==5.1.1 defusedxml==0.7.1 Deprecated==1.2.14 Django==4.2.8 django-admin-autocomplete-filter==0.7.1 django-admin-inline-paginator==0.3.0 django-admin-rangefilter==0.10.0 django-adminfilters==2.0.4 django-autocomplete-light==3.9.4 django-better-choices==1.17 django-cors-headers==3.11.0 django-countries==7.1 django-db-views==0.1.5 django-environ==0.11.2 django-extensions==3.2.3 django-filter==22.1 django-jsonform==2.17.0 django-localflavor==3.1 django-otp==1.1.6 django-pgtrigger==4.6.0 django-rosetta==0.9.5 django-simple-history==3.0.0 django-storages==1.13.2 djangorestframework==3.14.0 djangorestframework-camel-case==1.3.0 docutils==0.16 envier==0.4.0 exceptiongroup==1.1.2 executing==1.2.0 gocardless-pro==1.49.0 google-auth==2.22.0 google-auth-oauthlib==1.0.0 greenlet==2.0.2 gspread==3.7.0 gunicorn==20.1.0 idna==3.4 importlib-metadata==6.8.0 ipython==8.12.0 isodate==0.6.1 jedi==0.18.2 Jinja2==3.1.2 jmespath==1.0.1 kombu==5.2.4 lxml==4.9.3 MarkupSafe==2.1.3 matplotlib-inline==0.1.6 oauthlib==3.2.2 opentelemetry-api==1.19.0 parso==0.8.3 parsy==2.0 pdfkit==1.0.0 pexpect==4.8.0 pickleshare==0.7.5 platformdirs==3.9.1 polib==1.2.0 prompt-toolkit==3.0.39 protobuf==4.23.4 psycopg2==2.9.9 ptyprocess==0.7.0 pure-eval==0.2.2 pyasn1==0.5.0 pyasn1-modules==0.3.0 pycparser==2.21 Pygments==2.15.1 PyJWT==2.6.0 pypng==0.20220715.0 python-dateutil==2.8.2 python-json-logger==2.0.7 python-Levenshtein==0.12.2 python-stdnum==1.18 pytz==2023.3 PyYAML==6.0.1 qrcode==7.4.2 requests==2.31.0 requests-file==1.5.1 requests-oauthlib==1.3.1 requests-toolbelt==1.0.0 rsa==4.7.2 s3transfer==0.7.0 sentry-sdk==1.14.0 setproctitle==1.3.3 shortuuid==0.5.0 six==1.16.0 slack-sdk==3.26.1 SQLAlchemy==1.4.49 sqlparse==0.4.4 stack-data==0.6.2 stripe==5.4.0 systemdunitparser==0.2 thefuzz==0.19.0 toml==0.10.2 traitlets==5.9.0 typing_extensions==4.7.1 urllib3==1.26.18 vine==5.0.0 wcwidth==0.2.6 wrapt==1.15.0 xmltodict==0.13.0 zeep==4.1.0 zipp==3.16.2

How can we reproduce your problem?

This happens as soon as we start our application :shrug:

What is the result that you get?

As outlined above, an exception in Sentry, then no traces are sent to Datadog.

What is the result that you expected?

No exception, and traces sent to Datadog.

romainkomorndatadog commented 5 months ago

@pmourlanne , I'm wondering if there's something in the way your environment is set up that had you end up with a broken package. The PR that introduced the _build_git_packfiles_with_details function was the same that introduced its import, so I can't think of a reason why you would run into that import error.

I think I'll need your help to try and reproduce this, at least in terms of understanding how you're starting the application (eg: ddtrace-run or some other way) and what, if any, you're importing out of ddtrace. Which version of Python are you using?

With 3.11.0, using a simple virtual environment with ddtrace==2.4.0 installed, I'm able to do the import that's failing for you, eg:

% python -c "from ddtrace.ext.git import _build_git_packfiles_with_details; print(_build_git_packfiles_with_details.__module__)"
ddtrace.ext.git
(pip freeze details) ``` attrs==23.2.0 bytecode==0.15.1 cattrs==23.2.3 ddsketch==2.0.4 ddtrace==2.4.0 Deprecated==1.2.14 envier==0.5.0 importlib-metadata==6.11.0 opentelemetry-api==1.22.0 protobuf==4.25.1 six==1.16.0 typing_extensions==4.9.0 wrapt==1.16.0 xmltodict==0.13.0 zipp==3.17.0 ```

If anything, I would expect #7955 to be a more likely culprit (since it introduced a dependency on logging), which at least would map to the AttributeError: module 'our-project-name' has no attribute 'logging' error you're seeing in the end.

As far as why the imports happen, I lazily used a breakpoint() after ddtrace.ext.git's import statements , and just did an import ddtrace in a python interpreter, and the stack looks like:

(Pdb) w
...
-> from .settings import _config as config
-> self.loader.exec_module(module)
-> from .config import Config
-> self.loader.exec_module(module)
-> from ..internal import gitmetadata
...

which points to https://github.com/DataDog/dd-trace-py/blob/v2.4.0/ddtrace/settings/config.py#L20 :

from ..internal import gitmetadata

As a side note, we are relying on git metadata in a lot of places (and I'd say it's growing) to enrich the data we submit in spans, so maybe we'd have something to gain by moving some of ddtrace.ext.git's functionality to a utils module that isn't always imported along with ddtrace.ext.git.

benjaminrigaud commented 4 months ago

Hi, I am taking over this issue from @pmourlanne on our side.

We are reproducing the ImportError issue with ddtrace==2.6.0

Importing from ddtrace.ext.git is working fine:

$ python -c "from ddtrace.ext.git import _build_git_packfiles_with_details; print(_build_git_packfiles_with_details.__module__)"
ddtrace.ext.git

I am digging into this issue :+1:

benjaminrigaud commented 4 months ago

I reproduced the issue only one time after the installation.

All subsequents service restarts worked correctly :crying_cat_face:

I don't know if it is a good news or not: I have learned nothing and am not confident to move this update forward.

Just a hunch, but could it be related to the remote config change introduced in 2.4.0?

benjaminrigaud commented 4 months ago

I did another update scenario (from 2.3.5 to 2.6.0) and got another error:

Feb 13 08:16:28 ip-172-30-0-211 bash[289505]: 2024-02-13 08:16:28,644 ERROR [ddtrace._monkey] [_monkey.py:170] [dd.service=django dd.env=dev dd.version=v1.37.4-22-g039506f91 dd.trace_id=0 dd.span_id=0] - failed to import ddtrace module 'ddtrace.contrib.django' when patching on import
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]: Traceback (most recent call last):
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:   File "/srv/our_project/env/lib/python3.9/site-packages/ddtrace/_monkey.py", line 165, in on_import
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:     imported_module = importlib.import_module(path)
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:   File "/usr/local/lib/python3.9/importlib/__init__.py", line 127, in import_module
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:     return _bootstrap._gcd_import(name[level:], package, level)
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:   File "<frozen importlib._bootstrap>", line 1030, in _gcd_import
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:   File "<frozen importlib._bootstrap>", line 1007, in _find_and_load
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:   File "<frozen importlib._bootstrap>", line 986, in _find_and_load_unlocked
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:   File "<frozen importlib._bootstrap>", line 680, in _load_unlocked
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:   File "/srv/our_project/env/lib/python3.9/site-packages/ddtrace/internal/module.py", line 212, in _exec_module
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:   File "<frozen importlib._bootstrap_external>", line 850, in exec_module
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:   File "<frozen importlib._bootstrap>", line 228, in _call_with_frames_removed
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:   File "/srv/our_project/env/lib/python3.9/site-packages/ddtrace/contrib/django/__init__.py", line 187, in <module>
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:     from . import patch as _patch
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:   File "/srv/our_project/env/lib/python3.9/site-packages/ddtrace/internal/module.py", line 212, in _exec_module
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:   File "/srv/our_project/env/lib/python3.9/site-packages/ddtrace/contrib/django/patch.py", line 30, in <module>
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]:     from ddtrace.internal.core.event_hub import ResultType
Feb 13 08:16:28 ip-172-30-0-211 bash[289505]: ModuleNotFoundError: No module named 'ddtrace.internal.core.event_hub'; 'ddtrace.internal.core' is not a package

That wouldn't be solved after a reload.

 $ python -c "from ddtrace.internal.core.event_hub import ResultType"

Works fine.

benjaminrigaud commented 4 months ago

@romainkomorndatadog found something :+1:

I was reloading our gunicorn service (with systemctl).

A restart is working properly!

I don't know if it expected: but a reload isn't properly reloading the code of the updated ddtrace library.

I'll dig a bit more that aspect to understand how we are reloading our service and if (and how) we are restarting the gunicorn workers or not.

benjaminrigaud commented 4 months ago

Reloading the service is sending a HUP signal to gunicorn: it restarts new workers. These new workers should have a fresh and up-to-date ddtrace code.

But it still generates the ModuleNotFoundError: No module named 'ddtrace.internal.core.event_hub'; 'ddtrace.internal.core' is not a package as long as we don't restart.

https://docs.gunicorn.org/en/stable/signals.html#reload-the-configuration

Our service correctly respawning worker on a reload:

[2024-02-13 10:56:11 +0000] [316541] [INFO] Handling signal: hup
[2024-02-13 10:56:11 +0000] [316541] [INFO] Hang up: Master
[2024-02-13 10:56:11 +0000] [316908] [INFO] Booting worker with pid: 316908
[2024-02-13 10:56:11 +0000] [316547] [INFO] Worker exiting (pid: 316547)
[2024-02-13 10:56:11 +0000] [316551] [INFO] Worker exiting (pid: 316551)
[2024-02-13 10:56:11 +0000] [316549] [INFO] Worker exiting (pid: 316549)
[2024-02-13 10:56:11 +0000] [316910] [INFO] Booting worker with pid: 316910
[2024-02-13 10:56:11 +0000] [316911] [INFO] Booting worker with pid: 316911
[2024-02-13 10:56:12 +0000] [316541] [WARNING] Worker with pid 316549 was terminated due to signal 15
[2024-02-13 10:56:12 +0000] [316541] [WARNING] Worker with pid 316551 was terminated due to signal 15
[2024-02-13 10:56:12 +0000] [316541] [WARNING] Worker with pid 316547 was terminated due to signal 15
benjaminrigaud commented 4 months ago

I can reproduce the issue locally with the following steps:

benjaminrigaud commented 4 months ago

ddtrace-run is most likely one of the causes:

When used, it loads ddtrace in the master process (and we won't be able to reload that code). When not used, ddtrace is being loaded only in the workers.

A plausible explanation https://github.com/aio-libs/aiohttp/issues/2976#issuecomment-387011007

Apparently whenever the Gunicorn master process starts a child process, the child process "inherits" whatever the master process has already imported.

romainkomorndatadog commented 4 months ago

I'm going to pass this off to @mabdinur for sorting since it's not a CI Visibility issue.

@benjaminrigaud many thanks for the repro/debugging help.