Spec discussion: Exception and Error Handling in Meltano

[aaronsteers]

Opening this new discussion to come to a global set of standards for how we want to handle exceptions and errors within Meltano.

For this discussion (until another proposal is raised):

• Exceptions are things we may or may not handle up the call stack from where they occurred.
• Errors are things that will almost definitely cause failure (and therefor require clear and explicit messaging to the user).

Some issues we have as of now which we'd want to address:

1. Sometimes exceptions cause potentially confusing output to be printed. (per feat: Improve error log for cron validator and env var strict mode #6684)
2. We don't as of now have good standards on error handling.
3. We don't necessarily have clear dev guidance when handling Exceptions:

• For instance, is raise SomeException() sufficient or should we call logging.exception?

cc @pandemicsyn, @WillDaSilva, @edgarrmondragon, @meltano/engineering

[aaronsteers]

To start off the conversation, some steps we could start tackling:

1. Deliver feat: add rich exception formatting, configurable from logging.yaml #6640 and hopefully improve the printing of uncaught exceptions.
2. Confirm if feat: add rich exception formatting, configurable from logging.yaml #6640 on its own address/improves the situation in feat: Improve error log for cron validator and env var strict mode #6684.
3. Add to our dev standards some guidance on how to handle "Errors": what to print, how to log.
   • Related to Give http://melta.no troubleshooting help link when plugin fails, with CTA to Slack in web copy #6645
4. Use telemetry to find Exceptions that are not raising to the level of a handled Error.

[edgarrmondragon]

2. Confirm if feat: add rich exception formatting, configurable from logging.yaml #6640 on its own address/improves the situation in feat: Improve error log for cron validator and env var strict mode #6684.

@aaronsteers I don't think it will. At least for cron validation, the problem is the exception raised (BadCronError) is simply stringified by Click, so the exception message is extracted and printed in red 🤷‍♂️. The minimal intervention to improve the situation would be:

- raise BadCronError(schedule.interval)
+ raise BadCronError(f"{schedule.interval} is not a valid Cron expression or alias")

So, I wonder if this is a matter of being more thorough during PR review if the code raises exceptions explicitly. That is, check that the exception messages are useful.

[aaronsteers]

@edgarrmondragon - What about enforcing a common MeltanoErrorBase base class across the codebase.

And each error subclass would be required to properly stringify itself.

For BadCronError(expr), the stringify could be :

Invalid Cron expression or alias: '{expr}'. Please check that the cron expression is valid and try again.

And the class known how to render itself in context of the provided input arg sent to the Error constructor.

Wdyt?

[edgarrmondragon]

And each error subclass would be required to properly stringify itself.

@aaronsteers that would still require careful PR review when new exception subclasses are added, but it's slightly easier because only the class declaration has to be checked 👍.

[kgpayne]

This topic came up in Hacker News recently and got quite heated, so it isn’t just us figuring out Exceptions vs Errors 😅

[WillDaSilva]

We should ensure we are using raise-from whenever we are raising an exception from within an except where the exception we are raised was caused by the one that got us into the except block. For example, instead of this:

try:
    something_that_might_raise_an_exception()
except SomeExceptionType:
    raise OtherExceptionType('error message')

Do this:

try:
    something_that_might_raise_an_exception()
except SomeExceptionType as ex:
    raise OtherExceptionType('error message') from ex

This sets the __cause__ attribute of the exception being raised manually, which provides additional context in tracebacks, and can affect exception handling more broadly. If this is not done, then only the __context__ attribute will be set. If we want to ignore both the __cause__ and the __context__ of the exception (i.e. act like we're raising it from outside of the except block), we can use raise ... from None.

A good explanation of this can be found here: https://stackoverflow.com/a/24752607/5946921

[aaronsteers]

@WillDaSilva - Makes sense and while it may generally be a best practice, it probably would not hurt to make it an official standard and perhaps take a cleanup pass.

Should we add this to the handbook under Dev Standards, or by chance does anyone have a lint rule that we know of?

[edgarrmondragon]

There's probably some rule in WPS we can use.

[WillDaSilva]

Something that should be avoided that I've seen throughout the Meltano codebase is this pattern:

try:
    something_that_might_raise_an_exception()
except SomeExceptionType as ex:
    logger.error(f'Oh no! An error: {ex}')

This implicitly calls str on the exception, and results in the loss of the traceback. This is not to say that we should always hit the user with a full traceback, but losing it entirely is probably worse. If they're a power-user they have less info to work with, and will find it more difficult to get to the bottom of their problem. If they're not a power-user, and they just want to report what went wrong to us, they'll have less useful information to give us.

The stdlib traceback module provides the ability to get a string representation of a traceback, or print it (to a file/stderr/etc.).

Structured logging helps with this, because with that you can log the exception object itself, and then that can be processed as the user wishes (often with some difficulty, but better than losing the exception object altogether).

[aaronsteers]

@WillDaSilva - Thanks for bringing this up. To be completely honest, I actually have a definitive best practice for when logger.error or logger.exception should be called, rather than simply perform raise with the needed context.

One possible answer:

https://www.reddit.com/r/learnpython/comments/9l0aqb/comment/e74sfud/?utm_source=share&utm_medium=web2x&context=3

Use an exception when you want to communicate to the outer function calling this code that something went wrong. The outer function can then handle the exception and take the appropriate action (display a message to the user, try a different location,...).

Use logging for debugging purposes. When the program didn't behave as expected, you can see the logs in order to trace the execution path through the program. Don't use logging as a way to communicate with the end user.

Maybe a helpful thought experiment is whether we'd want to see the event in telemetry (or other debug artifacts) even when the exception otherwise can be handled gracefully and won't be in a stack trace. Presumably if the error/exception is fatal, it'll appear in the stack trace anyway.

Wdyt?

[edgarrmondragon]

@WillDaSilva would passing exc_info=True be acceptable

try:
    something_that_might_raise_an_exception()
except SomeExceptionType as ex:
    logger.error(f'Oh no! An error: {ex}', exc_info=True)

[WillDaSilva]

TIL @edgarrmondragon. That seems like a good way to handle it when using Python's logging module, since it attaches the exception tuple (ex_type, ex_value, ex_tb) to each log record, and then those records can be formatted as the consumers desire. That said, I was under the impression that we were in the process of transitioning towards exclusively using structlog instead of logging (though they integrate together in ways that are not entirely clear to me). @pandemicsyn are there any issues open to track our transition to structlog?

[edgarrmondragon]

Adding the structlog.processors.format_exc_info processor would allow to use exc_info just as with the stdlib logging.

[pandemicsyn]

@pandemicsyn are there any issues open to track our transition to structlog?

There was but I'm not sure if they're still open or wheren't copted along the way (its been over a year this point).

That said, I was under the impression that we were in the process of transitioning towards exclusively using structlog instead of logging (though they integrate together in ways that are not entirely clear to me).

It was supposed to be a piece meal change , but in the short term we had to support both AND actually get support for writing json formatted logs driven by a logging yaml (which was the original ask). Hence us not having a pure structlog driven config and using the https://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging pattern.

[WillDaSilva]

Related: #6641