Show update handler and ID in logging context

[drewhoskins-temporal]

Is your feature request related to a problem? Please describe.

It's hard to tell when log lines occurred within an update (or signal, or query) handler.

Describe the solution you'd like

I logged from within an update handler in the python SDK with self.logger.info
Imagining I saw this line in production, and I didn’t build the workflow, I could be confused as to why this code is getting executed. In fact, my update handler can also be called by the workflow itself, meaning it'd be nice if the context clarified whether I'm in an update handler or the main workflow.

Or I might want to grep the logs for all the times when an update/signal/query was called.

INFO:batch_orchestrator:This is my log message. ({'attempt': 1, 'namespace': 'default', 'run_id': '183ba64c-a415-492a-b569-a0e97d1a3114', 'task_queue': 'my-task-queue', 'workflow_id': 'inflate_product_prices-37acbbae-d941-4be8-8242-56f15a91d892', 'workflow_type': 'BatchOrchestrator'})

I'd love if the context or prefix listed which handler it's in somehow and perhaps whether it was a signal/update/query. In the case of an update, I'd like to see the update ID.

Additional context

Per-SDK Tickets

• Go Show update handler and ID in logging context sdk-go#1648
• .NET Show update handler and ID in logging context sdk-dotnet#351
• Python Show update handler and ID in logging context sdk-python#648
• TypeScript Show update handler and ID in logging context sdk-typescript#1532
• Java Show update handler and ID in logging context sdk-java#2237
• PHP Show update handler and ID in logging context sdk-php#512

[Quinn-With-Two-Ns]

Imagining I saw this line in production, and I didn’t build the workflow, I could be confused as to why this code is getting executed.

If you didn't write the workflow how will knowing what handler the log came from really help? What if a user wants to know all the logs that came from a particular update request? It doesn't help with query or signal, but we could consider adding the updateID as another KV in the logger.

[drewhoskins-temporal]

If you didn't write the workflow how will knowing what handler the log

came from really help? If I'm debugging, it will help me understand at-a-glance that this event came from an external source and not the workflow itself. Suppose the workflow is running, then there's an update, and the failure happens soon afterward, I can be like "a ha! This bug was triggered by an update!"

…

On Tue, Apr 23, 2024 at 5:32 PM Quinn Klassen ***@***.***> wrote: Imagining I saw this line in production, and I didn’t build the workflow, I could be confused as to why this code is getting executed. If you didn't write the workflow how will knowing what handler the log came from really help? What if a user wants to know all the logs that came from a particular update request? It doesn't help with query or signal, but we could consider adding the updateID as another KV in the logger. — Reply to this email directly, view it on GitHub <#466 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/BHV3GXIZUPOVF225K4AX2DTY634SHAVCNFSM6AAAAABGV4LGSSVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDANZTG4YTAMZQGY> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[Quinn-With-Two-Ns]

If you had multiple updates how would you tell which one caused your bug if all you have is the handle?

[cretz]

We/users can add logging scope if we need to in some langs, but in other langs that's non-standard. But it's important to understand that code that runs as a result of one of these interactions cannot always know it came from one of these interactions (e.g. a signal in Go is a channel, there's no handler, and e.g. many signal handlers just append something to a list to be processed by the primary coroutine). If it is important for a user to ship an action-specific logger around, they may.

In Python you might:

@workflow.update
async def do_update(self, in: MyUpdateInput) -> MyUpdateOutput:
    workflow.logger.info("This is my log message", extra={"handler": "do_update"})
    ...

^ This is how Python users are expected to add things to loggers. We only do workflow-level contextual information implicitly because the logger is workflow specific. Some languages (not Python) have a concept of scoped loggers, and some languages (Python) expect you to pass contextual information if you want it on your logs.

We can consider adding contextvars for logger, but in Python the common way is to carry state that the log caller sets on the log message or create an entirely new logger with an adapter (which is basically what we do at the workflow level). For other languages, we can discuss their most common way to add scope. But it is very important we are language idiomatic and that all languages approaches are understood well for issues like this.

[drewhoskins-temporal]

Max is bought in to doing something here. I'm tagging it as part of update GA.

[drewhoskins-temporal]

Interesting somewhat-related conversation about tracing with a customer. Because update is synchronous, and datadog doesn't support being part of two traces, they wanted their updates to be traced as part of the caller's traces rather than the workflow's.
I think that may underscore that the user will want to see logs associated with the update operation even moreso than the workflow. Even in the absence of tracing, logging the Update ID could help connect the client to the update handler in debugging scenarios, and the update name will greatly clarify what's going on.