From 5f115e98aaacc42d56bd9cfbffd2e1eb89b7ddab Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Tue, 26 Aug 2025 08:05:01 -0400 Subject: [PATCH 01/18] feat(logging): add datadog context --- warehouse/logging.py | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/warehouse/logging.py b/warehouse/logging.py index 9c383716cf62..7857e90dd9cc 100644 --- a/warehouse/logging.py +++ b/warehouse/logging.py @@ -36,6 +36,23 @@ def _create_id(request): return str(uuid.uuid4()) +def _add_datadog_context(logger, method_name, event_dict): + """Add Datadog trace context if available""" + try: + import ddtrace + span = ddtrace.tracer.current_span() + if span: + event_dict["dd.trace_id"] = str(span.trace_id) + event_dict["dd.span_id"] = str(span.span_id) + event_dict["dd.service"] = span.service + # deployment metadata + event_dict["dd.env"] = os.environ.get("DD_ENV", "development") + event_dict["dd.version"] = os.environ.get("DD_VERSION", "unknown") + except (ImportError, AttributeError): + pass + return event_dict + + def _create_logger(request): # This has to use **{} instead of just a kwarg because request.id is not # an allowed kwarg name. @@ -90,6 +107,7 @@ def includeme(config): structlog.stdlib.PositionalArgumentsFormatter(), structlog.processors.StackInfoRenderer(), structlog.processors.format_exc_info, + _add_datadog_context, RENDERER, ], logger_factory=structlog.stdlib.LoggerFactory(), From 33bef557059eb78190167d9e64dd6392dc0fa970 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Tue, 26 Aug 2025 08:32:28 -0400 Subject: [PATCH 02/18] fix(logging): unify the stamps of time --- warehouse/logging.py | 1 + 1 file changed, 1 insertion(+) diff --git a/warehouse/logging.py b/warehouse/logging.py index 7857e90dd9cc..f64abe68163c 100644 --- a/warehouse/logging.py +++ b/warehouse/logging.py @@ -105,6 +105,7 @@ def includeme(config): structlog.stdlib.add_logger_name, structlog.stdlib.add_log_level, structlog.stdlib.PositionalArgumentsFormatter(), + structlog.processors.TimeStamper(fmt="iso"), structlog.processors.StackInfoRenderer(), structlog.processors.format_exc_info, _add_datadog_context, From fcbedd018fb09fcbce6a895405c3017abb95da61 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Wed, 24 Sep 2025 13:54:45 -0500 Subject: [PATCH 03/18] feat(logging): celery structured --- warehouse/logging.py | 33 +++++++++++++++++++++++++++++++++ warehouse/tasks.py | 20 ++++++++++++++++++++ 2 files changed, 53 insertions(+) diff --git a/warehouse/logging.py b/warehouse/logging.py index f64abe68163c..bf6923a8ba56 100644 --- a/warehouse/logging.py +++ b/warehouse/logging.py @@ -53,6 +53,39 @@ def _add_datadog_context(logger, method_name, event_dict): return event_dict +def configure_celery_logging(logfile: str | None = None, loglevel: int = logging.INFO): + """Configure unified structlog logging for Celery that handles all log types.""" + processors = [ + structlog.contextvars.merge_contextvars, + structlog.processors.TimeStamper(fmt="iso"), + structlog.stdlib.add_log_level, + structlog.processors.StackInfoRenderer(), + structlog.processors.format_exc_info, + _add_datadog_context, + ] + formatter = structlog.stdlib.ProcessorFormatter( + processor=RENDERER, + foreign_pre_chain=processors, + ) + + handler = logging.FileHandler(logfile) if logfile else logging.StreamHandler() + handler.setFormatter(formatter) + + root = logging.getLogger() + root.handlers.clear() + root.addHandler(handler) + root.setLevel(loglevel) + + structlog.configure( + processors=processors + [ + structlog.stdlib.ProcessorFormatter.wrap_for_formatter, + ], + logger_factory=structlog.stdlib.LoggerFactory(), + wrapper_class=structlog.make_filtering_bound_logger(logging.INFO), + cache_logger_on_first_use=True, + ) + + def _create_logger(request): # This has to use **{} instead of just a kwarg because request.id is not # an allowed kwarg name. diff --git a/warehouse/tasks.py b/warehouse/tasks.py index d44ca0730822..74eebbf560fc 100644 --- a/warehouse/tasks.py +++ b/warehouse/tasks.py @@ -14,8 +14,10 @@ import celery.backends.redis import pyramid.scripting import pyramid_retry +import structlog import transaction import venusian +from celery import signals from kombu import Queue from pyramid.threadlocal import get_current_request @@ -37,6 +39,20 @@ logger = logging.getLogger(__name__) +# Celery signal handlers for unified structlog configuration +@signals.after_setup_logger.connect +def on_after_setup_logger(logger, loglevel, logfile, *args, **kwargs): + """Override Celery's default logging behavior with unified structlog configuration.""" + from warehouse.logging import configure_celery_logging + configure_celery_logging(logfile, loglevel) + + +@signals.task_prerun.connect +def on_task_prerun(sender, task_id, task, **_): + """Bind task metadata to contextvars for all logs within the task.""" + structlog.contextvars.bind_contextvars(task_id=task_id, task_name=task.name) + + class TLSRedisBackend(celery.backends.redis.RedisBackend): def _params_from_url(self, url, defaults): params = super()._params_from_url(url, defaults) @@ -302,6 +318,10 @@ def includeme(config: Configurator) -> None: REDBEAT_REDIS_URL=s["celery.scheduler_url"], # Silence deprecation warning on startup broker_connection_retry_on_startup=False, + # Disable Celery's logger hijacking for unified structlog control + worker_hijack_root_logger=False, + worker_log_format="%(message)s", + worker_task_log_format="%(message)s", ) config.registry["celery.app"].Task = WarehouseTask config.registry["celery.app"].pyramid_config = config From c566637f8da1be3704866f2ba3cbea2d71d1ee6a Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 10 Oct 2025 15:37:43 -0500 Subject: [PATCH 04/18] ci: make reformt --- warehouse/logging.py | 4 +++- warehouse/tasks.py | 3 ++- 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/warehouse/logging.py b/warehouse/logging.py index bf6923a8ba56..7072369b5471 100644 --- a/warehouse/logging.py +++ b/warehouse/logging.py @@ -40,6 +40,7 @@ def _add_datadog_context(logger, method_name, event_dict): """Add Datadog trace context if available""" try: import ddtrace + span = ddtrace.tracer.current_span() if span: event_dict["dd.trace_id"] = str(span.trace_id) @@ -77,7 +78,8 @@ def configure_celery_logging(logfile: str | None = None, loglevel: int = logging root.setLevel(loglevel) structlog.configure( - processors=processors + [ + processors=processors + + [ structlog.stdlib.ProcessorFormatter.wrap_for_formatter, ], logger_factory=structlog.stdlib.LoggerFactory(), diff --git a/warehouse/tasks.py b/warehouse/tasks.py index 74eebbf560fc..5ef75ca2dccd 100644 --- a/warehouse/tasks.py +++ b/warehouse/tasks.py @@ -17,8 +17,8 @@ import structlog import transaction import venusian -from celery import signals +from celery import signals from kombu import Queue from pyramid.threadlocal import get_current_request @@ -44,6 +44,7 @@ def on_after_setup_logger(logger, loglevel, logfile, *args, **kwargs): """Override Celery's default logging behavior with unified structlog configuration.""" from warehouse.logging import configure_celery_logging + configure_celery_logging(logfile, loglevel) From 837b73fdd12046ea2788d23828412e74e01409b3 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 10 Oct 2025 15:42:42 -0500 Subject: [PATCH 05/18] fix: import .. --- warehouse/logging.py | 1 + 1 file changed, 1 insertion(+) diff --git a/warehouse/logging.py b/warehouse/logging.py index 7072369b5471..822ed9a42374 100644 --- a/warehouse/logging.py +++ b/warehouse/logging.py @@ -1,6 +1,7 @@ # SPDX-License-Identifier: Apache-2.0 import logging.config +import os import threading import uuid From bfea6bf8f8122816ba771342eb4f747c0b59e208 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 10 Oct 2025 15:55:10 -0500 Subject: [PATCH 06/18] ci: line length weirdness --- warehouse/tasks.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/warehouse/tasks.py b/warehouse/tasks.py index 5ef75ca2dccd..9c87143a6dcc 100644 --- a/warehouse/tasks.py +++ b/warehouse/tasks.py @@ -42,7 +42,7 @@ # Celery signal handlers for unified structlog configuration @signals.after_setup_logger.connect def on_after_setup_logger(logger, loglevel, logfile, *args, **kwargs): - """Override Celery's default logging behavior with unified structlog configuration.""" + """Override Celery's default logging behavior with unified structlog configuration.""" # noqa: E501 from warehouse.logging import configure_celery_logging configure_celery_logging(logfile, loglevel) From 14f95bfb068d90727803d16873a553f59c1c588c Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 10 Oct 2025 15:58:13 -0500 Subject: [PATCH 07/18] ci: mypy :( --- warehouse/logging.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/warehouse/logging.py b/warehouse/logging.py index 822ed9a42374..705b192d5c9f 100644 --- a/warehouse/logging.py +++ b/warehouse/logging.py @@ -67,7 +67,7 @@ def configure_celery_logging(logfile: str | None = None, loglevel: int = logging ] formatter = structlog.stdlib.ProcessorFormatter( processor=RENDERER, - foreign_pre_chain=processors, + foreign_pre_chain=processors, # type: ignore[arg-type] ) handler = logging.FileHandler(logfile) if logfile else logging.StreamHandler() @@ -79,7 +79,7 @@ def configure_celery_logging(logfile: str | None = None, loglevel: int = logging root.setLevel(loglevel) structlog.configure( - processors=processors + processors=processors # type: ignore[arg-type] + [ structlog.stdlib.ProcessorFormatter.wrap_for_formatter, ], From 50b5868a728cdcc82ee2fc18ad1f363197c8af97 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 10 Oct 2025 16:16:53 -0500 Subject: [PATCH 08/18] test: add new things to expected asserts --- tests/unit/test_logging.py | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index 53ce3e1a6f3b..6d4baf1c7505 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -119,9 +119,11 @@ def test_includeme(monkeypatch, settings, expected_level): structlog.stdlib.filter_by_level, structlog.stdlib.add_logger_name, structlog.stdlib.add_log_level, - mock.ANY, - mock.ANY, + mock.ANY, # PositionalArgumentsFormatter + mock.ANY, # TimeStamper + mock.ANY, # StackInfoRenderer structlog.processors.format_exc_info, + mock.ANY, # _add_datadog_context wlogging.RENDERER, ], logger_factory=mock.ANY, @@ -133,10 +135,17 @@ def test_includeme(monkeypatch, settings, expected_level): configure.calls[0].kwargs["processors"][3], structlog.stdlib.PositionalArgumentsFormatter, ) + # timestamper #18843 assert isinstance( configure.calls[0].kwargs["processors"][4], + structlog.processors.TimeStamper, + ) + assert isinstance( + configure.calls[0].kwargs["processors"][5], structlog.processors.StackInfoRenderer, ) + # _add_datadog_context #18843 + assert configure.calls[0].kwargs["processors"][7] == wlogging._add_datadog_context assert isinstance( configure.calls[0].kwargs["logger_factory"], structlog.stdlib.LoggerFactory ) From 7ff43207e903c529e714b4cc260489a4b9c151c6 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 10 Oct 2025 16:26:37 -0500 Subject: [PATCH 09/18] test(ai): add tests for new dd context and expected celery structure Co-authored-by: Claude --- tests/unit/test_logging.py | 34 ++++++++++++++++++++++++++++++++++ 1 file changed, 34 insertions(+) diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index 6d4baf1c7505..100755d9ac10 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -153,3 +153,37 @@ def test_includeme(monkeypatch, settings, expected_level): pretend.call(wlogging._create_id, name="id", reify=True), pretend.call(wlogging._create_logger, name="log", reify=True), ] + + +def test_add_datadog_context(monkeypatch): + monkeypatch.setenv("DD_ENV", "production") + monkeypatch.setenv("DD_VERSION", "1.2.3") + + event_dict = {"event": "test"} + result = wlogging._add_datadog_context(None, None, event_dict) + + assert result["dd.env"] == "production" + assert result["dd.version"] == "1.2.3" + + +def test_add_datadog_context_with_span(monkeypatch): + """Test Datadog context with an active span.""" + import sys + + mock_span = pretend.stub(trace_id=123, span_id=456, service="test-svc") + mock_tracer = pretend.stub(current_span=lambda: mock_span) + mock_ddtrace = pretend.stub(tracer=mock_tracer) + + sys.modules["ddtrace"] = mock_ddtrace + monkeypatch.setenv("DD_ENV", "prod") + monkeypatch.setenv("DD_VERSION", "2.0") + + try: + event_dict = {"event": "test"} + result = wlogging._add_datadog_context(None, None, event_dict) + + assert result["dd.trace_id"] == "123" + assert result["dd.span_id"] == "456" + assert result["dd.service"] == "test-svc" + finally: + del sys.modules["ddtrace"] From 3f4b29ff2933f228177bd32f5da72b82d4116ffd Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 10 Oct 2025 16:26:55 -0500 Subject: [PATCH 10/18] test(ci): attain coverage for ci happiness Co-authored-by: Claude --- tests/unit/test_logging.py | 27 +++++++++++++++++++++++++++ 1 file changed, 27 insertions(+) diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index 100755d9ac10..48e362e0812a 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -187,3 +187,30 @@ def test_add_datadog_context_with_span(monkeypatch): assert result["dd.service"] == "test-svc" finally: del sys.modules["ddtrace"] + + +def test_configure_celery_logging(monkeypatch): + configure = pretend.call_recorder(lambda **kw: None) + monkeypatch.setattr(structlog, "configure", configure) + + mock_handler = pretend.stub(setFormatter=pretend.call_recorder(lambda f: None)) + mock_logger = pretend.stub( + handlers=pretend.stub(clear=pretend.call_recorder(lambda: None)), + setLevel=pretend.call_recorder(lambda l: None), + addHandler=pretend.call_recorder(lambda h: None), + removeHandler=pretend.call_recorder(lambda h: None), + ) + monkeypatch.setattr(logging, "getLogger", lambda: mock_logger) + monkeypatch.setattr(logging, "StreamHandler", lambda: mock_handler) + + wlogging.configure_celery_logging() + + # Verify handlers cleared and new one added + assert mock_logger.handlers.clear.calls == [pretend.call()] + assert len(mock_logger.addHandler.calls) == 1 + assert mock_logger.setLevel.calls == [pretend.call(logging.INFO)] + + # Verify processors + processors = configure.calls[0].kwargs["processors"] + assert structlog.contextvars.merge_contextvars in processors + assert wlogging._add_datadog_context in processors From 72a63401a38f654f84120a46f53fa1bc70c2afa2 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 10 Oct 2025 16:27:10 -0500 Subject: [PATCH 11/18] test(ci): moooore cover Co-authored-by: Claude --- tests/unit/test_tasks.py | 23 +++++++++++++++++++++++ 1 file changed, 23 insertions(+) diff --git a/tests/unit/test_tasks.py b/tests/unit/test_tasks.py index 27457d554bf0..c50f88ae5f4f 100644 --- a/tests/unit/test_tasks.py +++ b/tests/unit/test_tasks.py @@ -524,3 +524,26 @@ def test_includeme(env, ssl, broker_redis_url, expected_url, transport_options): assert config.add_request_method.calls == [ pretend.call(tasks._get_task_from_request, name="task", reify=True) ] + + +def test_on_after_setup_logger(monkeypatch): + configure_celery_logging = pretend.call_recorder(lambda logfile, loglevel: None) + monkeypatch.setattr( + "warehouse.logging.configure_celery_logging", configure_celery_logging + ) + + tasks.on_after_setup_logger("logger", "loglevel", "logfile") + + assert configure_celery_logging.calls == [pretend.call("logfile", "loglevel")] + + +def test_on_task_prerun(monkeypatch): + bind_contextvars = pretend.call_recorder(lambda **kw: None) + monkeypatch.setattr("structlog.contextvars.bind_contextvars", bind_contextvars) + + task = pretend.stub(name="test.task") + tasks.on_task_prerun(None, "task-123", task) + + assert bind_contextvars.calls == [ + pretend.call(task_id="task-123", task_name="test.task") + ] From 472c2cc562c960d51df3bda0b64f053ae40d2959 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 10 Oct 2025 16:38:39 -0500 Subject: [PATCH 12/18] ci: lint --- tests/unit/test_logging.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index 48e362e0812a..a5cb5b66be1d 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -196,9 +196,9 @@ def test_configure_celery_logging(monkeypatch): mock_handler = pretend.stub(setFormatter=pretend.call_recorder(lambda f: None)) mock_logger = pretend.stub( handlers=pretend.stub(clear=pretend.call_recorder(lambda: None)), - setLevel=pretend.call_recorder(lambda l: None), - addHandler=pretend.call_recorder(lambda h: None), - removeHandler=pretend.call_recorder(lambda h: None), + setLevel=pretend.call_recorder(lambda level: None), + addHandler=pretend.call_recorder(lambda add_handler: None), + removeHandler=pretend.call_recorder(lambda remove_handler: None), ) monkeypatch.setattr(logging, "getLogger", lambda: mock_logger) monkeypatch.setattr(logging, "StreamHandler", lambda: mock_handler) From 8e4a5b95449afed4953a2c627f7f8a32e3d2d066 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 10 Oct 2025 16:53:03 -0500 Subject: [PATCH 13/18] test: add case for no ddtrace for coverage happiness Co-authored-by: Claude --- tests/unit/test_logging.py | 27 +++++++++++++++++++++++++++ 1 file changed, 27 insertions(+) diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index a5cb5b66be1d..45fc9318ff2c 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -189,6 +189,33 @@ def test_add_datadog_context_with_span(monkeypatch): del sys.modules["ddtrace"] +def test_add_datadog_context_no_ddtrace(monkeypatch): + """Test Datadog context when ddtrace is not available.""" + # Block ddtrace import + # we just want to simulate ddtrace beiung unavailable + # to make coverage happy :) + import builtins + + original_import = builtins.__import__ + + def mock_import(name, *args, **kwargs): + if name == "ddtrace": + raise ImportError("ddtrace not available") + return original_import(name, *args, **kwargs) + + monkeypatch.setattr(builtins, "__import__", mock_import) + + event_dict = {"event": "test"} + result = wlogging._add_datadog_context(None, None, event_dict) + + # Should not have any dd fields when import fails + assert "dd.trace_id" not in result + assert "dd.span_id" not in result + assert "dd.service" not in result + assert "dd.env" not in result + assert "dd.version" not in result + + def test_configure_celery_logging(monkeypatch): configure = pretend.call_recorder(lambda **kw: None) monkeypatch.setattr(structlog, "configure", configure) From f1a9441ead1bcc2e86ff8c77c9e0ab64c813b22a Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 10 Oct 2025 17:02:43 -0500 Subject: [PATCH 14/18] test: fix because coverage hates me --- tests/unit/test_logging.py | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index 45fc9318ff2c..8e1e74b60b9e 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -191,18 +191,23 @@ def test_add_datadog_context_with_span(monkeypatch): def test_add_datadog_context_no_ddtrace(monkeypatch): """Test Datadog context when ddtrace is not available.""" + import sys + import builtins + # Block ddtrace import # we just want to simulate ddtrace beiung unavailable # to make coverage happy :) - import builtins - original_import = builtins.__import__ def mock_import(name, *args, **kwargs): if name == "ddtrace": - raise ImportError("ddtrace not available") + raise ImportError("No module named 'ddtrace'") return original_import(name, *args, **kwargs) + # Remove from sys.modules if present + if "ddtrace" in sys.modules: + del sys.modules["ddtrace"] + monkeypatch.setattr(builtins, "__import__", mock_import) event_dict = {"event": "test"} From 1bfdf035f2b02501c82172131fcd1faab9e0638c Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 17 Oct 2025 11:35:50 -0400 Subject: [PATCH 15/18] chore: remove datadog context --- tests/unit/test_logging.py | 70 -------------------------------------- warehouse/logging.py | 21 ------------ 2 files changed, 91 deletions(-) diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index 8e1e74b60b9e..c9514bb13885 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -123,7 +123,6 @@ def test_includeme(monkeypatch, settings, expected_level): mock.ANY, # TimeStamper mock.ANY, # StackInfoRenderer structlog.processors.format_exc_info, - mock.ANY, # _add_datadog_context wlogging.RENDERER, ], logger_factory=mock.ANY, @@ -144,8 +143,6 @@ def test_includeme(monkeypatch, settings, expected_level): configure.calls[0].kwargs["processors"][5], structlog.processors.StackInfoRenderer, ) - # _add_datadog_context #18843 - assert configure.calls[0].kwargs["processors"][7] == wlogging._add_datadog_context assert isinstance( configure.calls[0].kwargs["logger_factory"], structlog.stdlib.LoggerFactory ) @@ -155,72 +152,6 @@ def test_includeme(monkeypatch, settings, expected_level): ] -def test_add_datadog_context(monkeypatch): - monkeypatch.setenv("DD_ENV", "production") - monkeypatch.setenv("DD_VERSION", "1.2.3") - - event_dict = {"event": "test"} - result = wlogging._add_datadog_context(None, None, event_dict) - - assert result["dd.env"] == "production" - assert result["dd.version"] == "1.2.3" - - -def test_add_datadog_context_with_span(monkeypatch): - """Test Datadog context with an active span.""" - import sys - - mock_span = pretend.stub(trace_id=123, span_id=456, service="test-svc") - mock_tracer = pretend.stub(current_span=lambda: mock_span) - mock_ddtrace = pretend.stub(tracer=mock_tracer) - - sys.modules["ddtrace"] = mock_ddtrace - monkeypatch.setenv("DD_ENV", "prod") - monkeypatch.setenv("DD_VERSION", "2.0") - - try: - event_dict = {"event": "test"} - result = wlogging._add_datadog_context(None, None, event_dict) - - assert result["dd.trace_id"] == "123" - assert result["dd.span_id"] == "456" - assert result["dd.service"] == "test-svc" - finally: - del sys.modules["ddtrace"] - - -def test_add_datadog_context_no_ddtrace(monkeypatch): - """Test Datadog context when ddtrace is not available.""" - import sys - import builtins - - # Block ddtrace import - # we just want to simulate ddtrace beiung unavailable - # to make coverage happy :) - original_import = builtins.__import__ - - def mock_import(name, *args, **kwargs): - if name == "ddtrace": - raise ImportError("No module named 'ddtrace'") - return original_import(name, *args, **kwargs) - - # Remove from sys.modules if present - if "ddtrace" in sys.modules: - del sys.modules["ddtrace"] - - monkeypatch.setattr(builtins, "__import__", mock_import) - - event_dict = {"event": "test"} - result = wlogging._add_datadog_context(None, None, event_dict) - - # Should not have any dd fields when import fails - assert "dd.trace_id" not in result - assert "dd.span_id" not in result - assert "dd.service" not in result - assert "dd.env" not in result - assert "dd.version" not in result - - def test_configure_celery_logging(monkeypatch): configure = pretend.call_recorder(lambda **kw: None) monkeypatch.setattr(structlog, "configure", configure) @@ -245,4 +176,3 @@ def test_configure_celery_logging(monkeypatch): # Verify processors processors = configure.calls[0].kwargs["processors"] assert structlog.contextvars.merge_contextvars in processors - assert wlogging._add_datadog_context in processors diff --git a/warehouse/logging.py b/warehouse/logging.py index 705b192d5c9f..9c0a1ad50847 100644 --- a/warehouse/logging.py +++ b/warehouse/logging.py @@ -1,7 +1,6 @@ # SPDX-License-Identifier: Apache-2.0 import logging.config -import os import threading import uuid @@ -37,24 +36,6 @@ def _create_id(request): return str(uuid.uuid4()) -def _add_datadog_context(logger, method_name, event_dict): - """Add Datadog trace context if available""" - try: - import ddtrace - - span = ddtrace.tracer.current_span() - if span: - event_dict["dd.trace_id"] = str(span.trace_id) - event_dict["dd.span_id"] = str(span.span_id) - event_dict["dd.service"] = span.service - # deployment metadata - event_dict["dd.env"] = os.environ.get("DD_ENV", "development") - event_dict["dd.version"] = os.environ.get("DD_VERSION", "unknown") - except (ImportError, AttributeError): - pass - return event_dict - - def configure_celery_logging(logfile: str | None = None, loglevel: int = logging.INFO): """Configure unified structlog logging for Celery that handles all log types.""" processors = [ @@ -63,7 +44,6 @@ def configure_celery_logging(logfile: str | None = None, loglevel: int = logging structlog.stdlib.add_log_level, structlog.processors.StackInfoRenderer(), structlog.processors.format_exc_info, - _add_datadog_context, ] formatter = structlog.stdlib.ProcessorFormatter( processor=RENDERER, @@ -144,7 +124,6 @@ def includeme(config): structlog.processors.TimeStamper(fmt="iso"), structlog.processors.StackInfoRenderer(), structlog.processors.format_exc_info, - _add_datadog_context, RENDERER, ], logger_factory=structlog.stdlib.LoggerFactory(), From c83a08b3f5ee29c3dbc25043b0daa4cdb1fd9e36 Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 17 Oct 2025 11:38:23 -0400 Subject: [PATCH 16/18] chore: remove comments --- tests/unit/test_logging.py | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index c9514bb13885..fc0c23ade964 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -134,7 +134,6 @@ def test_includeme(monkeypatch, settings, expected_level): configure.calls[0].kwargs["processors"][3], structlog.stdlib.PositionalArgumentsFormatter, ) - # timestamper #18843 assert isinstance( configure.calls[0].kwargs["processors"][4], structlog.processors.TimeStamper, From 8cf01cac1c96eac6ecb56c5102c53ccabac8042e Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 17 Oct 2025 11:45:25 -0400 Subject: [PATCH 17/18] chore: format --- warehouse/tasks.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/warehouse/tasks.py b/warehouse/tasks.py index 9c87143a6dcc..60a59cb1f240 100644 --- a/warehouse/tasks.py +++ b/warehouse/tasks.py @@ -23,6 +23,7 @@ from pyramid.threadlocal import get_current_request from warehouse.config import Environment +from warehouse.logging import configure_celery_logging from warehouse.metrics import IMetricsService if typing.TYPE_CHECKING: @@ -42,9 +43,8 @@ # Celery signal handlers for unified structlog configuration @signals.after_setup_logger.connect def on_after_setup_logger(logger, loglevel, logfile, *args, **kwargs): - """Override Celery's default logging behavior with unified structlog configuration.""" # noqa: E501 - from warehouse.logging import configure_celery_logging - + """Override Celery's default logging behavior + with unified structlog configuration.""" configure_celery_logging(logfile, loglevel) From cb9aab10fae2f1be4ee0d68c454ce07e2b20d5ec Mon Sep 17 00:00:00 2001 From: Jacob Coffee Date: Fri, 17 Oct 2025 13:19:43 -0400 Subject: [PATCH 18/18] fix: double warpped logging from pyramid that inherits request method without request.id --- warehouse/tasks.py | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/warehouse/tasks.py b/warehouse/tasks.py index 60a59cb1f240..68b40ad74354 100644 --- a/warehouse/tasks.py +++ b/warehouse/tasks.py @@ -8,6 +8,7 @@ import time import typing import urllib.parse +import uuid import celery import celery.app.backends @@ -139,6 +140,10 @@ def get_request(self) -> Request: env["request"].remote_addr_hashed = hashlib.sha256( ("127.0.0.1" + registry.settings["warehouse.ip_salt"]).encode("utf8") ).hexdigest() + request_id = str(uuid.uuid4()) + env["request"].id = request_id + structlog.contextvars.bind_contextvars(**{"request.id": request_id}) + env["request"].log = structlog.get_logger("warehouse.request") self.request.update(pyramid_env=env) return self.request.pyramid_env["request"] # type: ignore[attr-defined]