Add Context-Aware Synchronous/Asynchronous Logging Adapters

[cswartzvi]

This PR is a follow-on to #1287 utilizing the new task submission and resolution hooks to create context-aware logging adapters.

Disclaimers:

• I fully realize this may be too much for base Hamilton. I have been using a version of this at work for a few months and it performs well. Please do not feel any sort of bad if this is rejected - I can easily continue to use it as a separate extension
• The details for context-aware logging, and structure of the logs, were larger inspired by prefect
• This branch is based on Add Task Submission / Return Hooks #1287 and will need to be rebased if/when accepted

Changes

This PR adds a pair of adapters (in hamiton.plugins.h_logging) named LoggingAdapter and AsyncLoggingAdapter that can be used to log the following state in a the execution of a graph (supporting both V1/V2 drivers where applicable):

• Graph start (GraphExecutionHook)
• Task grouping (TaskGroupingHook)
• Task submission (TaskSubmissionHook)
• Task pre-execution (TaskExecutionHook))
• Node pre-execution (NodeExecutionHook)
• Node post-execution (NodeExecutionHook)
• Task post-execution (TaskExecutionHook)
• Task resolution (TaskResolutionHook)
• Graph completion (GraphExecutionHook)

These adapters keep track of their current execution context by using an internal ContextVar. This allows the log to have a context dependent prefix, by way of an internal custom log adapter, such as

Graph run 'c7236c13-94ca-4e5e-85a6-2f32af054736' - Starting graph execution 

or

`Task 'expand-stargazer_url.0.block-stargazer_url' - Task completed [OK]

Additionally, a function called get_logger was added that returns the custom log adapter which the user can use to create context-aware logs from within a node. For example the following log inside node a...

from hamilton.plugins.h_logging import get_logger

def a() -> str:
    logger = get_logger("name_or_logger_or_none")
    logger.warning("Encountered a warning")

will generate the following:

Node 'a' - Encountered a warning

See the Notes section for some examples

How I tested this

I added tests for both LoggingAdapter and AsyncLoggingAdapter. The tests for LoggingAdapter examine the V1 driver with and without the FutureAdapter and the V2 driver with the synchronous, multi-threading, multi-process, ray, and dask task-based executors. The tests may be a little brittle because some are dependent on undocumented task id naming conventions. Open to suggestions 😄.

Examples

Here I would like to present some examples. I used a logging configuration based on rich - but any will suffice.

Synchronous - non-branching

Standard node-based Hamilton graphs using the LoggingAdapter...

def a() -> str:
    return "a"

def b(a: str) -> str:
    return a + " b"

def c(b: str) -> str:
    return b + " c"

will produce the following ...

INFO     Graph run '24fd50b2-760b-4cf2-b1e1-61476c18e9b3' - Starting graph execution
DEBUG    Node 'a' - Starting execution without dependencies
INFO     Node 'a' - Finished execution [OK]
DEBUG    Node 'b' - Starting execution with dependencies 'a'
INFO     Node 'b' - Finished execution [OK]
DEBUG    Node 'c' - Starting execution with dependencies 'b'
INFO     Node 'c' - Finished execution [OK]
INFO     Graph run '24fd50b2-760b-4cf2-b1e1-61476c18e9b3' - Finished graph execution [OK]

Synchronous - branching

Branching graphs with multiple possible paths using the LoggingAdapter (with or without the FutureAdapter)...

    def a() -> str:
        return "a"

    def b() -> str:
        return "b"

    def c() -> str:
        return "c"

    def d(a: str, b: str) -> str:
        return a + " " + b + " d"

    def e(c: str) -> str:
        return c + " e"

    def f(d: str, e: str) -> str:
        return d + " " + e + " f"

will produce the following (with a potentially different order)...

INFO     Graph run '31d4bc1d-8020-4e24-91a5-732a03497f1a' - Starting graph execution
DEBUG    Node 'c' - Submitting async node without dependencies
DEBUG    Node 'a' - Submitting async node without dependencies
DEBUG    Node 'b' - Submitting async node without dependencies
DEBUG    Node 'd' - Submitting async node with dependencies 'a', 'b'
DEBUG    Node 'e' - Submitting async node with dependencies 'c'
DEBUG    Node 'f' - Submitting async node with dependencies 'd', 'e'
INFO     Node 'c' - Finished execution [OK]
INFO     Node 'a' - Finished execution [OK]
INFO     Node 'b' - Finished execution [OK]
INFO     Node 'e' - Finished execution [OK]
INFO     Node 'd' - Finished execution [OK]
INFO     Node 'f' - Finished execution [OK]
INFO     Graph run '31d4bc1d-8020-4e24-91a5-732a03497f1a' - Finished graph execution [OK]

Asynchronous - Branching

Async branching graphs are also supported using the AsyncLoggingAdapter but must be used with the async driver. There is a little weakness in this adapter dealing with the current state of hooks in the async adapter - see the code for more details.

async def a() -> str:
    return "a"

async def b() -> str:
    return "b"

async def c() -> str:
    return "c"

async def d(a: str, b: str) -> str:
    return a + " " + b + " d"

async def e(c: str) -> str:
    return c + " e"

async def f(d: str, e: str) -> str:
    return d + " " + e + " f"

These will produce the following (again with a potentially different order)...

DEBUG    Node 'a' - Submitting async node without dependencies
DEBUG    Node 'b' - Submitting async node without dependencies
DEBUG    Node 'd' - Submitting async node with dependencies 'a', 'b'
DEBUG    Node 'c' - Submitting async node without dependencies
DEBUG    Node 'e' - Submitting async node with dependencies 'c'
DEBUG    Node 'f' - Submitting async node with dependencies 'd', 'e'
INFO     Node 'a' - Finished execution [OK]
INFO     Node 'b' - Finished execution [OK]
INFO     Node 'c' - Finished execution [OK]
INFO     Node 'd' - Finished execution [OK]
INFO     Node 'e' - Finished execution [OK]
INFO     Node 'f' - Finished execution [OK]
INFO     Graph run '38deee89-4a91-4253-b913-ce3c1e60b791' - Finished graph execution [OK]

Task based

Task-based executors (synchronous, threading, processing, ray, dask ,...) are also supported with the LoggingAdapter. Note however that user context logs from inside a node may (threading, ray) or may not (multiprocessing, dask) be supported. Some executors provide log pass throughs (ray) the produce slightly different results.

def b(a: int) -> int:
    return a

def c(b: int) -> Parallelizable[int]:
    for i in range(b):
        yield i

def d(c: int) -> int:
    return 2 * c

def e(d: Collect[int]) -> int:
    return sum(d)

def f(e: int) -> int:
    return e

These will produce the following (with a potentially different order) when a = 2...

INFO     Graph run 'dc4ec112-ba50-44ae-8b64-11b0ad099f74' - Starting graph execution
INFO     Graph run 'dc4ec112-ba50-44ae-8b64-11b0ad099f74' - Using inputs 'a'
INFO     Graph run 'dc4ec112-ba50-44ae-8b64-11b0ad099f74' - Dynamic DAG detected; task-based logging is enabled
DEBUG    Task 'a' - Initializing new task and submitting to executor
DEBUG    Task 'a' - Task completed [OK]
DEBUG    Task 'b' - Initializing new task and submitting to executor
DEBUG    Task 'b' - Starting execution
DEBUG    Task 'b' - Starting execution with dependencies 'a'
DEBUG    Task 'b' - Node 'b' - Finished execution [OK]
DEBUG    Task 'b' - Finished execution [Ok]
INFO     Task 'b' - Task completed [OK]
DEBUG    Task 'expand-c' - Initializing new task and submitting to executor
DEBUG    Task 'expand-c' - Starting execution of nodes 'c'
DEBUG    Task 'expand-c' - Starting execution with dependencies 'b'
DEBUG    Task 'expand-c' - Node 'c' - Finished execution [OK]
DEBUG    Task 'expand-c' - Finished execution [Ok]
INFO     Task 'expand-c' - Task completed [OK]
DEBUG    Task 'expand-c.0.block-c' - Spawning task and submitting to executor
DEBUG    Task 'expand-c.0.block-c' - Starting execution of nodes 'd'
DEBUG    Task 'expand-c.0.block-c' - Starting execution with dependencies 'c'
DEBUG    Task 'expand-c.0.block-c' - Node 'd' - Finished execution [OK]
DEBUG    Task 'expand-c.0.block-c' - Finished execution [Ok]
INFO     Task 'expand-c.0.block-c' - Task completed [OK]
DEBUG    Task 'expand-c.1.block-c' - Spawning task and submitting to executor
DEBUG    Task 'expand-c.1.block-c' - Starting execution of nodes 'd'
DEBUG    Task 'expand-c.1.block-c' - Starting execution with dependencies 'c'
DEBUG    Task 'expand-c.1.block-c' - Node 'd' - Finished execution [OK]
DEBUG    Task 'expand-c.1.block-c' - Finished execution [Ok]
INFO     Task 'expand-c.1.block-c' - Task completed [OK]
DEBUG    Task 'collect-c' - Initializing new task and submitting to executor
DEBUG    Task 'collect-c' - Starting execution of nodes 'e'
DEBUG    Task 'collect-c' - Starting execution with dependencies 'd'
DEBUG    Task 'collect-c' - Node 'e' - Finished execution [OK]
DEBUG    Task 'collect-c' - Finished execution [Ok]
INFO     Task 'collect-c' - Task completed [OK]
DEBUG    Task 'f' - Initializing new task and submitting to executor
DEBUG    Task 'f' - Starting execution
DEBUG    Task 'f' - Starting execution with dependencies 'e'
DEBUG    Task 'f' - Node 'f' - Finished execution [OK]
DEBUG    Task 'f' - Finished execution [Ok]
INFO     Task 'f' - Task completed [OK]
INFO     Graph run 'dc4ec112-ba50-44ae-8b64-11b0ad099f74' - Finished graph execution [OK]

Sorry that was alot! 😅 If you like what you see, please let me know! Note that I have not added docs for this yet - happily planning to do so after an initial review!

Checklist

• PR has an informative and human-readable title (this will be pulled into the release notes)
• Changes are limited to a single goal (no scope creep)
• Code passed the pre-commit check & code is left cleaner/nicer than when first encountered.
• Any change in functionality is tested
• New functions are documented (with a description, list of inputs, and expected output)
• Placeholder code is flagged / future TODOs are captured in comments
• Project documentation has been updated if adding/changing functionality.

[ellipsis-dev]

❌ Changes requested. Reviewed everything up to aaef55b in 3 minutes and 0 seconds

More details

• Looked at 1617 lines of code in 12 files
• Skipped 0 files when reviewing.
• Skipped posting 22 drafted comments based on config settings.

1. hamilton/plugins/h_logging.py:81

• Draft comment:
  Consider adding a comment on how the extra fields (override_context, skip_context, node_context) affect the log message prefix for developers.
• Reason this comment was not posted:
  Confidence changes required: 20% <= threshold 50%
  None

2. hamilton/plugins/h_logging.py:143

• Draft comment:
  Document the logging adapter's handling of input/override nodes in run_before_task_execution. Clarify why logging is skipped for tasks matching these sets.
• Reason this comment was not posted:
  Confidence changes required: 20% <= threshold 50%
  None

3. hamilton/plugins/h_logging.py:309

• Draft comment:
  Ensure that the signature of run_after_task_resolution matches interface expectations. Although the 'result' parameter is omitted here, consider documenting that decision.
• Reason this comment was not posted:
  Confidence changes required: 30% <= threshold 50%
  None

4. tests/plugins/test_logging.py:145

• Draft comment:
  Use helper functions or inline comments to clarify the brittle nature of tests that depend on task naming conventions.
• Reason this comment was not posted:
  Confidence changes required: 20% <= threshold 50%
  None

5. tests/plugins/test_logging.py:351

• Draft comment:
  Consider adding a comment clarifying the expected behavior of the log when using overrides, ensuring consistency with the LoggingAdapter’s logic.
• Reason this comment was not posted:
  Confidence changes required: 10% <= threshold 50%
  None

6. tests/lifecycle/lifecycle_adapters_for_testing.py:54

• Draft comment:
  The global 'sequence_number' used in ExtendToTrackCalls may not be safe in concurrent or parallel test environments. Consider using an instance-level counter or a thread‐safe mechanism.
• Reason this comment was not posted:
  Comment was not on a location in the diff, so it can't be submitted as a review comment.

7. tests/lifecycle/test_lifecycle_adapters_end_to_end_task_based.py:130

• Draft comment:
  Magic numbers in assertions (e.g. '2 + 5 + 1 + 1') reduce clarity. Consider defining named constants or adding comments to explain the expected counts for each task group.
• Reason this comment was not posted:
  Comment was not on a location in the diff, so it can't be submitted as a review comment.

8. tests/plugins/test_logging.py:320

• Draft comment:
  The test 'test_logging_parallel_nodes' uses a hardcoded set of debug log messages in 'local_debug_log'. This brittle check may fail if internal log message formats change. Consider using pattern‐based matching or more flexible assertions.
• Reason this comment was not posted:
  Decided after close inspection that this draft comment was likely wrong and/or not actionable: usefulness confidence = 0% vs. threshold = 50%
  While the comment raises a valid point about test brittleness, this appears to be an intentional design choice. The test is specifically checking the exact format of log messages across different executors. The test author is aware of this, as evidenced by their comment. Pattern matching could make the test less precise, which may defeat its purpose of catching unintended changes to log formats.
  The comment suggests a reasonable alternative approach with pattern matching. This could make the tests more maintainable if log formats need to change frequently.
  However, exact string matching serves a purpose here - it acts as a safeguard against unintended changes to log formats, which could be important for users relying on these formats.
  The comment should be deleted since the test's brittleness is intentional and already acknowledged in the code comments. The exact string matching appears to be a deliberate choice to catch log format changes.

9. tests/plugins/test_logging.py:370

• Draft comment:
  The test 'test_logging_with_overrides' asserts that the info log message ends with a specific string ('Using overrides 'a''). Relying on exact string comparisons for log messages can be brittle. Consider asserting for a substring or using regex-based matching to allow flexibility in log formatting.
• Reason this comment was not posted:
  Decided after close inspection that this draft comment was likely wrong and/or not actionable: usefulness confidence = 10% vs. threshold = 50%
  Since this is a test specifically for the logging functionality, being precise about the log message format is actually important. The test is verifying the exact format of log messages produced by the logging adapter. Making the test more flexible could hide changes to the log format that we want to catch. Additionally, this test follows the same pattern as other logging tests in the file that use endswith() checks.
  The comment has a valid point about test brittleness in general - exact string matching can make tests fragile. However, in this specific case, we're testing a logging system where the exact format matters.
  While reducing test brittleness is generally good, in this case the precise log format is part of the API we're testing. The existing approach using endswith() is consistent with other tests in the file and appropriate for testing logging output.
  The comment should be deleted. The current test approach using endswith() is appropriate for testing logging functionality where the exact message format matters.

10. hamilton/execution/executors.py:24

• Draft comment:
  The docstring for TaskFuture currently says 'This a clean wrapper over a python future...'. It would be clearer to say 'This is a clean wrapper over a Python future...'.
• Reason this comment was not posted:
  Comment was on unchanged code.

11. hamilton/execution/executors.py:102

• Draft comment:
  In the docstring of base_execute_task, 'a diciontary of the results' should be corrected to 'a dictionary of the results'.
• Reason this comment was not posted:
  Comment was not on a location in the diff, so it can't be submitted as a review comment.

12. hamilton/execution/grouping.py:176

• Draft comment:
  Typo found: 'betweeen' should be corrected to 'between'.
• Reason this comment was not posted:
  Comment was not on a location in the diff, so it can't be submitted as a review comment.

13. hamilton/execution/grouping.py:203

• Draft comment:
  Typo found: 'Fina all the Parallelizable[] nodes in the DAG' should be 'Find all the Parallelizable[] nodes in the DAG'.
• Reason this comment was not posted:
  Comment was not on a location in the diff, so it can't be submitted as a review comment.

14. hamilton/execution/grouping.py:233

• Draft comment:
  Typo found in comment: 'In thie case of a strange override' should be 'In this case of a strange override'.
• Reason this comment was not posted:
  Comment was not on a location in the diff, so it can't be submitted as a review comment.

15. hamilton/execution/grouping.py:392

• Draft comment:
  Typo found: 'guarenteed topological order' should be 'guaranteed topological order'.
• Reason this comment was not posted:
  Comment was not on a location in the diff, so it can't be submitted as a review comment.

16. hamilton/lifecycle/api.py:472

• Draft comment:
  Typo: In the docstring for 'run_after_task_resolution', change 'executor,on' to 'executor, on' (add a space after the comma) for better readability.
• Reason this comment was not posted:
  Decided after close inspection that this draft comment was likely wrong and/or not actionable: usefulness confidence = 10% vs. threshold = 50%
  While the comment is technically correct about a missing space, the review rules emphasize not making purely informative comments or obvious/unimportant changes. A missing space in a docstring is a very minor formatting issue that doesn't impact code functionality or readability significantly.
  The typo does slightly impact docstring readability. Documentation quality is important for developer experience.
  While documentation quality matters, this is an extremely minor formatting issue that doesn't significantly impact understanding. The rules specifically say not to make unimportant comments.
  The comment should be deleted as it points out an extremely minor formatting issue that doesn't meaningfully impact code quality or understanding.

17. hamilton/lifecycle/base.py:287

• Draft comment:
  Typo in the docstring of BaseDoValidateInput: change 'maches' to 'matches'.
• Reason this comment was not posted:
  Comment was not on a location in the diff, so it can't be submitted as a review comment.

18. hamilton/plugins/h_logging.py:389

• Draft comment:
  Typo: Change 'has bee submitted' to 'has been submitted' in the asynchronous adapter comment.
• Reason this comment was not posted:
  Decided after close inspection that this draft comment was likely wrong and/or not actionable: usefulness confidence = 10% vs. threshold = 50%
  While this is technically a typo, it's in a comment and doesn't affect functionality. The meaning is still clear despite the typo. The rules emphasize focusing on actual code changes and avoiding trivial changes. Fixing comment typos is not one of the priority rules listed.
  The typo does make the code slightly less professional. Documentation quality is important for maintainability.
  However, this is an extremely minor issue in an internal comment, not user-facing documentation. The meaning is still perfectly clear. Opening a PR just to fix this would create more overhead than value.
  This comment should be deleted as it points out an extremely minor typo in a comment that doesn't impact code functionality or clarity.

19. hamilton/plugins/h_logging.py:128

• Draft comment:
  Typographical issue: Remove the extra closing parenthesis in the bullet list items for 'Task pre-execution (TaskExecutionHook))' and 'Task post-execution (TaskExecutionHook))'. The entries should have matching parentheses.
• Reason this comment was not posted:
  Marked as duplicate.

20. tests/lifecycle/lifecycle_adapters_for_testing.py:56

• Draft comment:
  Typographical issue: In the comment on line 56, consider changing "cause" to "because" and "its" to "it's" for clarity.
• Reason this comment was not posted:
  Comment was not on a location in the diff, so it can't be submitted as a review comment.

21. tests/lifecycle/test_lifecycle_adapters_end_to_end_task_based.py:154

• Draft comment:
  Typographical error: In the comment for the task_ids assertion, 'at lease one for the inner task that failed' should be 'at least one for the inner task that failed'.
• Reason this comment was not posted:
  Comment was not on a location in the diff, so it can't be submitted as a review comment.

22. tests/plugins/test_logging.py:256

• Draft comment:
  Typo in comment: "NOTE: These test is brittle..." should probably be "NOTE: This test is brittle..." or "These tests are brittle..." for proper grammar.
• Reason this comment was not posted:
  Decided after close inspection that this draft comment was likely wrong and/or not actionable: usefulness confidence = 0% vs. threshold = 50%
  While this is technically correct, our rules say to only keep comments that require code changes. Grammar fixes in comments are very low value and don't affect functionality. The comment is still understandable despite the minor grammar error.
  The grammar error could make the codebase look less professional. Poor grammar in comments could set a bad precedent.
  While professionalism matters, this is a very minor issue in a test file. The meaning is still clear and fixing grammar in comments is not a high priority use of review time.
  Delete this comment as it only addresses grammar in a comment rather than suggesting any meaningful code changes.

Workflow ID: wflow_3QRUI1P2obJZcqsP

---

Want Ellipsis to fix these issues? Tag @ellipsis-dev in a comment. You can customize Ellipsis with 👍 / 👎 feedback, review rules, user-specific overrides, quiet mode, and more.

[cswartzvi]

Ahh I see, ray and dask have separate testing environments - I will disable those tests for now.

[cswartzvi]

Tests are still failing due to xgboost (also in #1287) and an issue with my multiprocessing test (I had a feeling that one might cause problems, so much so I skipif-it on windows).

[elijahbenizzy]

Looks good, very little blast radius. Let's get #1287 merged first then merge this.

[elijahbenizzy]

Looks good -- once we merge the other we can merge this! Will likely want to rebase off of main after that due to the squash and merge.

[cswartzvi]

@elijahbenizzy I rebased on my branch from #1287 and updated the hook names