Deserialize traceback from stack trace string in Temporal failures if able

[cretz]

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

We chain errors when converting from failures by setting __cause__, but there is a report that the chained errors are not logged like normally chained errors

EDIT: We don't rehydrate the traceback from the stack trace string

Describe the solution you'd like

Make sure we log chained errors normally and write a test to ensure it

EDIT: Java parses their string stack trace back to stack trace elements, so we should too. See https://github.com/ionelmc/python-tblib/blob/dd926c1e5dc5bbe5e1fc494443bbac8970c7d3ee/src/tblib/__init__.py#L200 for an example of how to do this.

[nathanielobrown]

Ok, I looked into this bit further and I realized that the chaining is working, but you don't get any stack traces. To be honest I just didn't notice the exception chain without associated stack traces, particularly because the top level WorkflowError had a big stack trace.

I know that the stack trace for ApplicationErrors is available (e.cause.cause.failure.stack_trace) I wonder if there's a way to "rehydrate" the stack trace so it displays as if the exception was raised locally. It looks like https://github.com/ionelmc/python-tblib does this sort of thing.

From what I see there is no stack trace attached for ActivityErrors. It would be nice to have stack traces for these as well, but I guess it's less important and I imagine if it's not in the error prototbuf you're not about to add it.

[cretz]

I wonder if there's a way to "rehydrate" the stack trace so it displays as if the exception was raised locally

My fear of "rehydrating" the stack trace is if it's not from Python. These stack traces may come from any language. It is normal to have a Python workflow execute a Go activity and vice-versa. Let me check what other languages do here.

From what I see there is no stack trace attached for ActivityErrors.

This is because ActivityError is never "raised", it is only used as a wrapper by the server. It'd be the actual raised error (i.e. ApplicationError) that would have a stack trace.

[nathanielobrown]

My fear of "rehydrating" the stack trace is if it's not from Python. These stack traces may come from any language. It is normal to have a Python workflow execute a Go activity and vice-versa. Let me check what other languages do here.

I suppose you could just try "rehydration" and then fallback to no traceback or a string representation.

[cretz]

I suppose you could just try "rehydration" and then fallback to no traceback or a string representation.

I have confirmed this is exactly what Java does. My only concern now is how to parse the traceback. I would rather not have a third party library it at all possible just for this use case. And I also would rather not come up with my own string format for tracebacks that will work on all versions of Python (because I doubt I can trust default traceback string formats from version to version).

The question now becomes how important is it to rehydrate Python stack traces compared to the effort and brittleness of the solution?

[nathanielobrown]

The question now becomes how important is it to rehydrate Python stack traces compared to the effort and brittleness of the solution?

I say, if Java did it why not Python? I think it would be a nice thing. You could just pull the minimal code needed from tblib into sdk-python. I'd be up for working on something like this, but I haven't been able to get the development setup working on my M1 Mac 😔

Alternatively we could just rely on logging. This is what I'm used to with Dramatiq which is what I currently use for task processing and it's not soo bad.

[cretz]

Java's stack trace element string format is a bit more stable from version to version.

Regardless, yeah we can do this. I think we'd just take tblib.Traceback.from_string which seems to have an expectation on Python traceback string format. So maybe it is more stable than I realize. And of course we'd have some tests to ensure it continues to work. I will change the title of this issue to add this functionality. This shouldn't be hard to implement, I'll probably get to it before next release.

[cretz]

I am bit concerned about doing this now as I see the string format is changing in 3.11 to include more detail. It seems relying on traceback string format is rough. It breaks on 3.11 with the library you linked at https://github.com/ionelmc/python-tblib and other traceback parsers I've seen (e.g. bolton). I wonder if we can just ask that users:

err = my_exception
while isinstance(err, FailureError):
    if err.failure.stack_trace:
        try:
            err.__traceback__ = tblib.Traceback.from_string(err.failure.stack_trace)
        except TracebackParseError:
            pass
    err = err.__cause__

[nathanielobrown]

You are so right, I can see that being a big problem. Maybe the thing is just to think of the developer story ("as a developer I want to see where in my code an error is occurring when I am testing locally") and make sure it's covered in some way?

For example, I'm pretty happy with my custom activity decorator that logs exceptions in activities. So maybe improving the default logging would work too, but I feel like having clear stack traces be displayed in stdout/stderr by default is important.

Under the same developer story, it's still slightly bugs me that you don't get any stack trace for the workflow portion of errors. I feel like the activities are more important as that's were the errors should mostly be, but it would be very nice to have stack traces everywhere.

[cretz]

Any suggestions here? Options as I see them:

• Deserialize into traceback - brittle because traceback strings are non-standard across versions
• Ask the user to extract the traces themselves - may be asking too much of the user
• Have custom logger - we need to respect their choice on logging
• Put the stack trace inside the exception args - then normal str() calls return way more than the message
• Our own equivalent of https://docs.python.org/3/library/traceback.html#traceback.print_exception - still requires users actually call it

Are there any options I missed? Any preferred option there?

[nathanielobrown]

I think I'm partial to logging. Maybe a way to think of it is "default logging" and then user's can still setup their own system if they like. I personally use loguru but it's fairly interoperable/based on the core Python logging, and I feel like that's how things generally are in Python logging. I also use the rich logging handler as my handler for nicely formatted and colored output. So I think it's OK to depend on Python logging. I feel like if you have nice default logging out of the box it also gives a great feel to first time users while power users still know how to reconfigure things how they like it.

I'm not sure where you would log exceptions from (worker process? workflow process?) but I'm looking forward to seeing what you decide.

[cretz]

The concern is not depending on Python logging, the concern is that the caller calls their own logger at their own time to log the exception. We can't inject the stack trace only at logging time without forcing the user to use some kind of helper explicitly.

How do I make logger.exception("OH NO") print these stack traces without including them in the exception args (i.e. what str()) would show)? We can make helpers they can call, but I am not aware of a way to do this implicitly. Do you have a more concrete suggestion? Can you show code of how a user might use their logger to log this exception with string stack traces?

[nathanielobrown]

The concern is not depending on Python logging, the concern is that the caller calls their own logger at their own time to log the exception. We can't inject the stack trace only at logging time without forcing the user to use some kind of helper explicitly.

If they want to do that, they can just disable the temporal section of the logging tree. I feel it's not so widely known that you can do this, but you can always add a note to the SDK docs the help point people in the right direction.

How do I make logger.exception("OH NO") print these stack traces without including them in the exception args (i.e. what str()) would show)? We can make helpers they can call, but I am not aware of a way to do this implicitly. Do you have a more concrete suggestion? Can you show code of how a user might use their logger to log this exception with string stack traces?

Possibly you could log exceptions for actions directly from the action worker, and then this issue goes away. Then you lose the exception chain, but I personally don't find the current exception chain very useful because it basically says "A workflow failed and the source was an application error with this message" with no other information about how those things are linked. So, as a developer, if I see "my workflow failed due to an ApplicationError" along with a separate, logged, stack trace for the ApplicationError I likely understand what happened.

Logging application errors local to the activity feels less pure, but might be more useful in practice for local development and then in production you would probably rely more on the temporal UI anyway.

As to logging as string stack trace, I think you would just have to use logger.error rather than logger.exception. As I understand it, logger.exception calls logger.error but passes exception information to be formatted. We have already formatted stack trace, so logger.error might be fine.

[cretz]

Possibly you could log exceptions for actions directly from the action worker, and then this issue goes away.

I do log as debug with full stack traces at

sdk-python/temporalio/worker/workflow_instance.py

Lines 1120 to 1123 in 0392468

	logger.debug(
	f"Workflow raised failure with run ID {self._info.run_id}",
	exc_info=True,
	)

and

sdk-python/temporalio/worker/activity.py

Lines 442 to 444 in 0392468

	temporalio.activity.logger.debug(
	"Completing as failed", exc_info=True
	)

, but errors are a normal thing and I don't think we should log each one at a higher log level by default. But of course any user can catch/log their own exceptions or use an interceptor to log.

The issue of client not seeing stack traces does not go away though, because the client does not get the stack trace for a failed activity or workflow in the client-side log by default.

Then you lose the exception chain

Exception chain will always remain. We serialize hierarchical exception causes in all SDKs.

Logging application errors local [...]

Sure, nobody is stopping users from doing that. Granted it shouldn't be the default I don't think.

As to logging as string stack trace [...]

I am not following the concrete suggestion here. Regardless of what exc_info is set as (True on logger.exception by default, False otherwise), the point is the traceback is not present.

Here is a simple problem request:

"Can you make Temporal stack traces appear on the client when they use their logger?"

Everything else about how a user may want to log on the worker side or manually extract the stack trace string out is fine and doable, but it does not solve the problem. I think we either need to solve this problem or tell users their alternatives (e.g. "use X helper when logging" and/or "log on the worker side and just accept client side logging doesn't have stack traces", etc).