[Bug] logging adapter does not include extra attributes?

[jmdacruz]

What are you really trying to do?

I'm trying to use structured logging with the Python SDK, using the extra attributes to provide more context to log entries. The Python SDK seems to honor existing attributes when adding the activity/workflow contextual info:

sdk-python/temporalio/activity.py

Lines 374 to 376 in 1fa36c2

	extra = kwargs.get("extra", None) or {}
	extra["activity_info"] = context.info()
	kwargs["extra"] = extra

Describe the bug

When enabling basic logging for one of the Python samples, using a format string that references an extra attribute that is provided in all log entries (on workflow, activity, and main entry point for the app), the logging calls inside the workflow and activities raises a KeyError exception because it can't find the attribute. The same logging call on the main() entry point works just fine

Minimal Reproduction

On the https://github.com/temporalio/samples-python repo, apply the following diff (to file hello/hello_activity.py):

diff --git a/hello/hello_activity.py b/hello/hello_activity.py
index 6615b55..e7716ef 100644
--- a/hello/hello_activity.py
+++ b/hello/hello_activity.py
@@ -20,7 +20,8 @@ class ComposeGreetingInput:
 # Basic activity that logs and does string concatenation
 @activity.defn
 async def compose_greeting(input: ComposeGreetingInput) -> str:
-    activity.logger.info("Running activity with parameter %s" % input)
+    # Logging a record with extra attribute "foo" here causes a "KeyError" exception
+    activity.logger.info("Running activity with parameter %s" % input, extra={"foo": "in activity"})
     return f"{input.greeting}, {input.name}!"
 
 
@@ -29,7 +30,8 @@ async def compose_greeting(input: ComposeGreetingInput) -> str:
 class GreetingWorkflow:
     @workflow.run
     async def run(self, name: str) -> str:
-        workflow.logger.info("Running workflow with parameter %s" % name)
+        # Logging a record with extra attribute "foo" here causes a "KeyError" exception
+        workflow.logger.info("Running workflow with parameter %s" % name, extra={"foo": "in workflow"})
         return await workflow.execute_activity(
             compose_greeting,
             ComposeGreetingInput("Hello", name),
@@ -39,7 +41,12 @@ class GreetingWorkflow:
 
 async def main():
     # Uncomment the line below to see logging
-    # logging.basicConfig(level=logging.INFO)
+    # Including attribute "foo" on the log format
+    logging.basicConfig(level=logging.INFO, format="--- %(message)s --- %(foo)s")
+
+    # Logging a record with extra attribute "foo" here works fine
+    logger = logging.getLogger("root")
+    logger.info("logging in main", extra={"foo": "in main"})
 
     # Start client
     client = await Client.connect("localhost:7233")

Run the example against temporalite, started like:

temporalite start --ephemeral --namespace=default

The expected result is that all 3 log entries are printed, with the foo attribute. The actual result is that only the entry generated by the main() function is printed, and the two entries on the workflow and activity fail with a KeyError exception when trying to index the foo attribute.

Environment/Versions

• OS and processor: Intel Mac, Monterey
• Temporal Version: temporalite version (devel) (server 1.19.1), Python SDK with latest commit temporalio/samples-python@a4f0a05
• Are you using Docker or Kubernetes or building Temporal from source?: No, running directly with Python 3.10 and 3.11, using temporalite

[cretz]

Confirmed, this is caused by us calling calling super.process() in our logging adapter which does override extra: https://github.com/python/cpython/blob/aad5f6a89125ad4529ab6ed5add693064351df1a/Lib/logging/__init__.py#L1825. Will fix.

[jmdacruz]

@cretz I can create a PR removing those calls on all the LoggerAdapters.

[cretz]

@jmdacruz - Sure, would be much appreciated! Otherwise I was gonna get to it probably early next week

[jmdacruz]

@cretz I'm taking a stab at this by adding a common LoggerAdapter that changes the default behavior of the process(...) method by adding the self.extra attributes to the kwargs["extra"] (if this is there, else reverts to the current behavior). This is overkill now, because the singleton instance of the adapter is created with extra=None, but it could prove useful in the future if you decide to add extra attributes on the singleton.

Do you think this makes sense, or should I just remove the calls to super.process(...)?

[cretz]

Just remove the super call

[jmdacruz]

Done, creating PR now

[danmarinescu]

While #280 did fix the issue above it causes another problem. Say I create a logger like this

logger = workflow.LoggerAdapter(logging.getLogger(__name__), extra={'some_key':'some_val'})

then when the current implementation of process is called the extra dict set on the LoggerAdapter will not be included. See for reference the implementation in the LoggerAdapter superclass:

if self.merge_extra and "extra" in kwargs:
    kwargs["extra"] = {**self.extra, **kwargs["extra"]}
else:
    kwargs["extra"] = self.extra
return msg, kwargs

You can see that since we're no longer calling super.process() we are also using self.extra.

Imo the right fix here would be to:

• change the LoggerAdapter initializer implementation in Temporal to accept a merge_extra param like the superclass
• revert the above fix, i.e. call super.process() at the start of the process method

[cretz]

Thanks! When this issue was solved there was no merge_extra.

Imo the right fix here would be to:

• change the LoggerAdapter initializer implementation in Temporal to accept a merge_extra param like the superclass
• revert the above fix, i.e. call super.process() at the start of the process method

We can't really call super and have this problem solved because merge_extra was only added in Python 3.13 and we support more versions than that. Arguably we should have never accepted extra in the constructor and instead told users that if they wanted extra data, they needed to subclass and override process instead of instantiating.

It sounds like we may need to support our own form of merge_extra and default it to False which will continue to do the same behavior as today. Or maybe we should only support merge_extra in newer Python versions. I have opened #892.

In the meantime, I would recommend subclassing and overriding process to get the extra data needed.