From 2fb189dabcb0d5fc057355b9e0ecf538e76f1337 Mon Sep 17 00:00:00 2001 From: Daniel Alley Date: Sat, 17 Jan 2026 23:26:56 -0500 Subject: [PATCH 1/6] Propagate task "profile options" to any child tasks spawned by that task closes #7219 --- CHANGES/7219.bugfix | 1 + pulpcore/tasking/tasks.py | 11 +++++++++-- 2 files changed, 10 insertions(+), 2 deletions(-) create mode 100644 CHANGES/7219.bugfix diff --git a/CHANGES/7219.bugfix b/CHANGES/7219.bugfix new file mode 100644 index 0000000000..4788c96a70 --- /dev/null +++ b/CHANGES/7219.bugfix @@ -0,0 +1 @@ +"profile options" designated using the X-Task-Diagnostics feature should be propagated to child tasks. \ No newline at end of file diff --git a/pulpcore/tasking/tasks.py b/pulpcore/tasking/tasks.py index c187bd9195..50655c3bee 100644 --- a/pulpcore/tasking/tasks.py +++ b/pulpcore/tasking/tasks.py @@ -336,6 +336,13 @@ async def adispatch( def get_task_payload( function_name, task_group, args, kwargs, resources, versions, immediate, deferred, app_lock ): + """Create arguments for creation of a new task""" + current_task = Task.current() + profile_options = x_task_diagnostics_var.get(None) + # If this task is being spawned by another task, we should inherit the profile options + # from the current task. + if current_task: + profile_options = current_task.profile_options payload = { "state": TASK_STATES.WAITING, "logging_cid": (get_guid()), @@ -343,12 +350,12 @@ def get_task_payload( "name": function_name, "enc_args": args, "enc_kwargs": kwargs, - "parent_task": Task.current(), + "parent_task": current_task, "reserved_resources_record": resources, "versions": versions, "immediate": immediate, "deferred": deferred, - "profile_options": x_task_diagnostics_var.get(None), + "profile_options": profile_options, "app_lock": app_lock, } return payload From d9461fa9b98d317d17d534d617af7266f97fea70 Mon Sep 17 00:00:00 2001 From: Daniel Alley Date: Sun, 18 Jan 2026 12:49:04 -0500 Subject: [PATCH 2/6] Remove needlessly verbose debug logging These logs just aren't very helpful, and they're extremely verbose, to the point where they inflate log size by orders of magnitude and meaningfully slow execution. --- pulpcore/plugin/stages/api.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/pulpcore/plugin/stages/api.py b/pulpcore/plugin/stages/api.py index ded0e372ee..3f4156978f 100644 --- a/pulpcore/plugin/stages/api.py +++ b/pulpcore/plugin/stages/api.py @@ -76,7 +76,6 @@ async def run(self): content = await self._in_q.get() if content is None: break - log.debug("%(name)s - next: %(content)s.", {"name": self, "content": content}) yield content async def batches(self, minsize=500): @@ -171,7 +170,6 @@ async def put(self, item): if item is None: raise ValueError(_("(None) not permitted.")) await self._out_q.put(item) - log.debug("{name} - put: {content}".format(name=self, content=item)) def __str__(self): return "[{id}] {name}".format(id=id(self), name=self.__class__.__name__) From 13c39e0f9efa9efec34b011639bd4a87d619f6c7 Mon Sep 17 00:00:00 2001 From: Daniel Alley Date: Fri, 16 Jan 2026 23:29:34 -0500 Subject: [PATCH 3/6] Add task-specific log capturing to task diagnostics mechanism TASK_DIAGNOSTICS and X-Task-Diagnostics can now capture all logs for specific tasks. Because the logs are specific to the task, the logs are linear and not broken up by unrelated logs from other services/workers/tasks. Assisted By: Claude closes #7215 --- CHANGES/7215.feature | 1 + docs/dev/learn/tasks/diagnostics.md | 3 +- pulpcore/app/settings.py | 3 +- pulpcore/tasking/_util.py | 45 +++++++++++++++++++++++++++++ 4 files changed, 50 insertions(+), 2 deletions(-) create mode 100644 CHANGES/7215.feature diff --git a/CHANGES/7215.feature b/CHANGES/7215.feature new file mode 100644 index 0000000000..20d24923aa --- /dev/null +++ b/CHANGES/7215.feature @@ -0,0 +1 @@ +Added a "logs" option to the TASK_DIAGNOSTICS / X-Task-Diagnostics feature - dumps task-specific logs into a profile artifact. diff --git a/docs/dev/learn/tasks/diagnostics.md b/docs/dev/learn/tasks/diagnostics.md index 514c28f992..e07b475a54 100644 --- a/docs/dev/learn/tasks/diagnostics.md +++ b/docs/dev/learn/tasks/diagnostics.md @@ -35,7 +35,8 @@ The following diagnostics are supported currently: - memray: Dumps a profile which can be processed with `memray`, which shows which lines and functions were responsible for the most allocations at the time of peak RSS of the process - +- logs: + Dumps all logs specific to the task. Formatting not guaranteed to be identical. ## Memory Logging diff --git a/pulpcore/app/settings.py b/pulpcore/app/settings.py index e653aef0e5..64e1a9bcb6 100644 --- a/pulpcore/app/settings.py +++ b/pulpcore/app/settings.py @@ -382,8 +382,9 @@ # lines and functions, at the time of peak RSS of the task process. This adds significant # runtime overhead to the task process, 20-40%. Tweaking code might be warranted for # some advanced settings. +# * "logs" - Dumps the logs specific to each task. # NOTE: "memray" and "pyinstrument" require additional packages to be installed on the system. -TASK_DIAGNOSTICS = [] # ["memory", "pyinstrument", "memray"] +TASK_DIAGNOSTICS = [] # ["memory", "pyinstrument", "memray", "logs"] ANALYTICS = True diff --git a/pulpcore/tasking/_util.py b/pulpcore/tasking/_util.py index 7274d7cb8c..b6d23d6da1 100644 --- a/pulpcore/tasking/_util.py +++ b/pulpcore/tasking/_util.py @@ -121,6 +121,8 @@ def _execute_task_and_profile(task, profile_options): _execute_task = _pyinstrument_diagnostic_decorator(temp_dir, _execute_task) if "memray" in profile_options: _execute_task = _memray_diagnostic_decorator(temp_dir, _execute_task) + if "logs" in profile_options: + _execute_task = _logging_decorator(temp_dir, _execute_task) _execute_task(task) @@ -218,6 +220,49 @@ def __memray_diagnostic_decorator(task): return __memray_diagnostic_decorator +def _logging_decorator(temp_dir, func): + def __logging_decorator(task): + log_file_path = os.path.join(temp_dir, "task_logs.log") + + # Create a file handler that captures all logging levels + file_handler = logging.FileHandler(log_file_path, mode="w", encoding="utf-8") + file_handler.setLevel(logging.NOTSET) # Capture all levels + + # Create a formatter for consistent log formatting + formatter = logging.Formatter( + "%(asctime)s - %(name)s - %(levelname)s - %(message)s", datefmt="%Y-%m-%d %H:%M:%S" + ) + file_handler.setFormatter(formatter) + + # Get the root logger to capture all logs + root_logger = logging.getLogger() + + try: + # Add the handler to the root logger + root_logger.addHandler(file_handler) + + # Execute the task + func(task) + finally: + # Always remove the handler and restore original level + root_logger.removeHandler(file_handler) + file_handler.close() + + # Save the log file as a ProfileArtifact + artifact = Artifact.init_and_validate(log_file_path) + try: + # it's unlikely for a log file to be identical, but we retain the same check as the + # other decorators + artifact.save() + except IntegrityError: + artifact = Artifact.objects.get(sha256=artifact.sha256) + + ProfileArtifact.objects.get_or_create(artifact=artifact, name="task_logs", task=task) + _logger.info("Created task logging diagnostic data.") + + return __logging_decorator + + def dispatch_scheduled_tasks(): # Warning, dispatch_scheduled_tasks is not race condition free! now = timezone.now() From bf1c85b6d4a53d96353c5e836af7a92d0a78ddac Mon Sep 17 00:00:00 2001 From: Daniel Alley Date: Sat, 17 Jan 2026 22:50:40 -0500 Subject: [PATCH 4/6] Enable the file logger to access DEBUG logs for an individual task Temporarily change the root logger's log level, but make sure that the console logger is still only logging at INFO level. closes #7214 --- CHANGES/7214.feature | 1 + docs/dev/learn/tasks/diagnostics.md | 2 ++ pulpcore/app/settings.py | 5 ++++- pulpcore/tasking/_util.py | 18 ++++++++++++++---- pulpcore/tasking/tasks.py | 15 +++++++-------- 5 files changed, 28 insertions(+), 13 deletions(-) create mode 100644 CHANGES/7214.feature diff --git a/CHANGES/7214.feature b/CHANGES/7214.feature new file mode 100644 index 0000000000..bae4d16c82 --- /dev/null +++ b/CHANGES/7214.feature @@ -0,0 +1 @@ +Added a "debug-logs" option to the TASK_DIAGNOSTICS / X-Task-Diagnostics feature - dumps task-specific logs into a profile artifact at a DEBUG level. \ No newline at end of file diff --git a/docs/dev/learn/tasks/diagnostics.md b/docs/dev/learn/tasks/diagnostics.md index e07b475a54..cabbc4ef8c 100644 --- a/docs/dev/learn/tasks/diagnostics.md +++ b/docs/dev/learn/tasks/diagnostics.md @@ -37,6 +37,8 @@ The following diagnostics are supported currently: responsible for the most allocations at the time of peak RSS of the process - logs: Dumps all logs specific to the task. Formatting not guaranteed to be identical. +- debug-logs: + Same as the `logs` option except it exports logs at a DEBUG level, whether or not the system is configured to print DEBUG logs otherwise. ## Memory Logging diff --git a/pulpcore/app/settings.py b/pulpcore/app/settings.py index 64e1a9bcb6..0c3005058a 100644 --- a/pulpcore/app/settings.py +++ b/pulpcore/app/settings.py @@ -260,6 +260,7 @@ "handlers": { "console": { "class": "logging.StreamHandler", + "level": "INFO", "formatter": "simple", "filters": ["correlation_id"], } @@ -383,8 +384,10 @@ # runtime overhead to the task process, 20-40%. Tweaking code might be warranted for # some advanced settings. # * "logs" - Dumps the logs specific to each task. +# * "debug-logs" - Same as "logs" but it exports logs at a DEBUG level, even if the system is +# otherwise not configured to print DEBUG logs. # NOTE: "memray" and "pyinstrument" require additional packages to be installed on the system. -TASK_DIAGNOSTICS = [] # ["memory", "pyinstrument", "memray", "logs"] +TASK_DIAGNOSTICS = [] # ["memory", "pyinstrument", "memray", "logs", "debug-logs"] ANALYTICS = True diff --git a/pulpcore/tasking/_util.py b/pulpcore/tasking/_util.py index b6d23d6da1..3982598ca3 100644 --- a/pulpcore/tasking/_util.py +++ b/pulpcore/tasking/_util.py @@ -121,8 +121,10 @@ def _execute_task_and_profile(task, profile_options): _execute_task = _pyinstrument_diagnostic_decorator(temp_dir, _execute_task) if "memray" in profile_options: _execute_task = _memray_diagnostic_decorator(temp_dir, _execute_task) - if "logs" in profile_options: - _execute_task = _logging_decorator(temp_dir, _execute_task) + + is_debug = "debug-logs" in profile_options + if "logs" in profile_options or is_debug: + _execute_task = _logging_decorator(temp_dir, is_debug, _execute_task) _execute_task(task) @@ -220,7 +222,7 @@ def __memray_diagnostic_decorator(task): return __memray_diagnostic_decorator -def _logging_decorator(temp_dir, func): +def _logging_decorator(temp_dir, is_debug, func): def __logging_decorator(task): log_file_path = os.path.join(temp_dir, "task_logs.log") @@ -236,15 +238,23 @@ def __logging_decorator(task): # Get the root logger to capture all logs root_logger = logging.getLogger() + original_level = root_logger.level try: # Add the handler to the root logger root_logger.addHandler(file_handler) + if is_debug: + # Temporarily lower the root logger level to allow all messages through + # The existing handlers maintain their own levels, so they won't be affected + root_logger.setLevel(logging.NOTSET) + # Execute the task func(task) finally: - # Always remove the handler and restore original level + # Always restore original level and remove the handler + if is_debug: + root_logger.setLevel(original_level) root_logger.removeHandler(file_handler) file_handler.close() diff --git a/pulpcore/tasking/tasks.py b/pulpcore/tasking/tasks.py index 50655c3bee..168de8b8e9 100644 --- a/pulpcore/tasking/tasks.py +++ b/pulpcore/tasking/tasks.py @@ -66,7 +66,11 @@ def _execute_task(task): with with_task_context(task): task.set_running() domain = get_domain() + try: + # If this task is being spawned by another task, we should inherit the profile options + # from the current task. + ctx_token = x_task_diagnostics_var.set(task.profile_options) log_task_start(task, domain) task_function = get_task_function(task) result = task_function() @@ -79,6 +83,7 @@ def _execute_task(task): task.set_completed(result) log_task_completed(task, domain) send_task_notification(task) + x_task_diagnostics_var.reset(ctx_token) return result return None @@ -337,12 +342,6 @@ def get_task_payload( function_name, task_group, args, kwargs, resources, versions, immediate, deferred, app_lock ): """Create arguments for creation of a new task""" - current_task = Task.current() - profile_options = x_task_diagnostics_var.get(None) - # If this task is being spawned by another task, we should inherit the profile options - # from the current task. - if current_task: - profile_options = current_task.profile_options payload = { "state": TASK_STATES.WAITING, "logging_cid": (get_guid()), @@ -350,12 +349,12 @@ def get_task_payload( "name": function_name, "enc_args": args, "enc_kwargs": kwargs, - "parent_task": current_task, + "parent_task": Task.current(), "reserved_resources_record": resources, "versions": versions, "immediate": immediate, "deferred": deferred, - "profile_options": profile_options, + "profile_options": x_task_diagnostics_var.get(None), "app_lock": app_lock, } return payload From a1b0f24e033183ec9f8e64bd740842049fc79bcd Mon Sep 17 00:00:00 2001 From: Daniel Alley Date: Wed, 18 Feb 2026 10:35:25 -0500 Subject: [PATCH 5/6] Move to task var handling to contexts.py --- pulpcore/app/contexts.py | 17 +++++++++++++---- pulpcore/middleware.py | 4 +--- pulpcore/tasking/tasks.py | 7 +------ 3 files changed, 15 insertions(+), 13 deletions(-) diff --git a/pulpcore/app/contexts.py b/pulpcore/app/contexts.py index 76737ed155..01f6da0ee5 100644 --- a/pulpcore/app/contexts.py +++ b/pulpcore/app/contexts.py @@ -8,6 +8,7 @@ _current_task = ContextVar("current_task", default=None) _current_user_func = ContextVar("current_user", default=lambda: None) _current_domain = ContextVar("current_domain", default=None) +x_task_diagnostics_var = ContextVar("x_profile_task") @contextmanager @@ -44,11 +45,15 @@ def with_domain(domain): @contextmanager def with_task_context(task): with with_domain(task.pulp_domain), with_guid(task.logging_cid), with_user(task.user): - token = _current_task.set(task) + task_token = _current_task.set(task) + # If this task is being spawned by another task, we should inherit the profile options + # from the current task. + diagnostics_token = x_task_diagnostics_var.set(task.profile_options) try: yield finally: - _current_task.reset(token) + x_task_diagnostics_var.reset(diagnostics_token) + _current_task.reset(task_token) @asynccontextmanager @@ -59,8 +64,12 @@ def _fetch(task): domain, user = await _fetch(task) with with_domain(domain), with_guid(task.logging_cid), with_user(user): - token = _current_task.set(task) + task_token = _current_task.set(task) + # If this task is being spawned by another task, we should inherit the profile options + # from the current task. + diagnostics_token = x_task_diagnostics_var.set(task.profile_options) try: yield finally: - _current_task.reset(token) + x_task_diagnostics_var.reset(diagnostics_token) + _current_task.reset(task_token) diff --git a/pulpcore/middleware.py b/pulpcore/middleware.py index f31966d5ce..b1a72a5dad 100644 --- a/pulpcore/middleware.py +++ b/pulpcore/middleware.py @@ -1,7 +1,6 @@ import time import re -from contextvars import ContextVar from os import environ from django.http.response import Http404 @@ -10,6 +9,7 @@ from pulpcore.metrics import init_otel_meter from pulpcore.app.models import Domain +from pulpcore.app.contexts import x_task_diagnostics_var from pulpcore.app.util import ( get_worker_name, normalize_http_status, @@ -17,8 +17,6 @@ set_domain, ) -x_task_diagnostics_var = ContextVar("x_profile_task") - class DomainMiddleware: """ diff --git a/pulpcore/tasking/tasks.py b/pulpcore/tasking/tasks.py index 168de8b8e9..9d9cb3c785 100644 --- a/pulpcore/tasking/tasks.py +++ b/pulpcore/tasking/tasks.py @@ -21,7 +21,7 @@ get_domain, get_prn, ) -from pulpcore.app.contexts import with_task_context, awith_task_context +from pulpcore.app.contexts import with_task_context, awith_task_context, x_task_diagnostics_var from pulpcore.constants import ( TASK_FINAL_STATES, TASK_INCOMPLETE_STATES, @@ -30,7 +30,6 @@ TASK_WAKEUP_HANDLE, TASK_WAKEUP_UNBLOCK, ) -from pulpcore.middleware import x_task_diagnostics_var from pulpcore.tasking.kafka import send_task_notification _logger = logging.getLogger(__name__) @@ -68,9 +67,6 @@ def _execute_task(task): domain = get_domain() try: - # If this task is being spawned by another task, we should inherit the profile options - # from the current task. - ctx_token = x_task_diagnostics_var.set(task.profile_options) log_task_start(task, domain) task_function = get_task_function(task) result = task_function() @@ -83,7 +79,6 @@ def _execute_task(task): task.set_completed(result) log_task_completed(task, domain) send_task_notification(task) - x_task_diagnostics_var.reset(ctx_token) return result return None From 321d472e1ee427a9dc9bb1a15c07e95b9eb133f6 Mon Sep 17 00:00:00 2001 From: Daniel Alley Date: Wed, 21 Jan 2026 08:09:27 -0500 Subject: [PATCH 6/6] Minor docs fix --- docs/dev/guides/pull-request-walkthrough.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/dev/guides/pull-request-walkthrough.md b/docs/dev/guides/pull-request-walkthrough.md index feb143ae03..d9865a2e81 100644 --- a/docs/dev/guides/pull-request-walkthrough.md +++ b/docs/dev/guides/pull-request-walkthrough.md @@ -14,9 +14,9 @@ Please be sure to follow the [Pulp policy on AI Usage](site:help/more/governance 1. Add `functional tests` or `unit tests` where appropriate and ensure tests are passing on the CI. -2. Add a [`CHANGES entry`](site:pulpcore/docs/dev/guides/git/#markdown-header-changelog-update). +2. Add a [`CHANGES entry`](site:pulpcore/docs/dev/guides/git/#changelog-update). 3. Update relevent `documentation`. Please build the docs to test! -4. If the PR is a simple feature or a bugfix, [`rebase and squash`](site:pulpcore/docs/dev/guides/git/#markdown-header-rebasing-and-squashing) to a single commit. +4. If the PR is a simple feature or a bugfix, [`rebase and squash`](site:pulpcore/docs/dev/guides/git/#rebasing-and-squashing) to a single commit. If the PR is a complex feature, make sure that all commits are cleanly separated and have meaningful commit messages. 5. Make sure you tag commits with `closes #IssueNumber` or `ref #IssueNumber` when working on a tracked issue. 6. If AI was used, make sure you are following the [Pulp policy on AI Usage](site:help/more/governance/ai_policy/)