From 5ccd192897b6ff06e08135642c9d62da81bec557 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 eb270250c7..6e3da256e4 100644 --- a/pulpcore/tasking/tasks.py +++ b/pulpcore/tasking/tasks.py @@ -352,6 +352,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()), @@ -359,12 +366,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 9df0e02b128e8b9c8d11d97d81222e7119772fb5 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 bbef636c06ed928e67dc5bbc1588e3c2ce5ac047 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 b6000c7da1..00311bd725 100644 --- a/pulpcore/app/settings.py +++ b/pulpcore/app/settings.py @@ -374,8 +374,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 704a15ad26f151516dbabcd71686b920287fa9b8 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 | 17 +++++++++++++---- 4 files changed, 20 insertions(+), 5 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 00311bd725..bbe015ad56 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"], } @@ -375,8 +376,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..de23721d65 100644 --- a/pulpcore/tasking/_util.py +++ b/pulpcore/tasking/_util.py @@ -121,8 +121,9 @@ 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) + if "logs" in profile_options or "debug-logs" in profile_options: + is_debug = "debug-logs" in profile_options + _execute_task = _logging_decorator(temp_dir, is_debug, _execute_task) _execute_task(task) @@ -220,7 +221,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 +237,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() From d6f79d632c186a633a7d99bab03b3070be9e2aca Mon Sep 17 00:00:00 2001 From: Daniel Alley Date: Wed, 21 Jan 2026 08:09:27 -0500 Subject: [PATCH 5/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/) From 09960f0075ad0a04de7845ca65d5aa4a65dbf6f6 Mon Sep 17 00:00:00 2001 From: Daniel Alley Date: Thu, 22 Jan 2026 08:51:36 -0500 Subject: [PATCH 6/6] temp commit --- pulpcore/tasking/_util.py | 5 +++-- pulpcore/tasking/tasks.py | 15 +++++++-------- 2 files changed, 10 insertions(+), 10 deletions(-) diff --git a/pulpcore/tasking/_util.py b/pulpcore/tasking/_util.py index de23721d65..3982598ca3 100644 --- a/pulpcore/tasking/_util.py +++ b/pulpcore/tasking/_util.py @@ -121,8 +121,9 @@ 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 or "debug-logs" in profile_options: - is_debug = "debug-logs" in profile_options + + 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) diff --git a/pulpcore/tasking/tasks.py b/pulpcore/tasking/tasks.py index 6e3da256e4..0806838a6c 100644 --- a/pulpcore/tasking/tasks.py +++ b/pulpcore/tasking/tasks.py @@ -70,7 +70,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() @@ -89,6 +93,7 @@ def _execute_task(task): else: task.set_completed(result) log_task_completed(task, domain) + x_task_diagnostics_var.reset(ctx_token) send_task_notification(task) @@ -353,12 +358,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()), @@ -366,12 +365,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