Removing log_and_raise

[davidorme]

Description

This PR removes the logger.log_and_raise function and replaces all instances of its use with explicit LOGGER.critical() calls and then Exception raises (or re-raises in the case of try: except: blocks).

I've also updated a couple of function/method docstrings that were missing Raises: sections and updated the docstrings for core.logger to describe expected LOGGER practice when Exceptions occur.

Fixes #125

Type of change

• New feature (non-breaking change which adds functionality)
• Optimization (back-end change that speeds up the code)
• Bug fix (non-breaking change which fixes an issue)

Key checklist

• Make sure you've run the pre-commit checks: $ pre-commit run -a
• All tests pass: $ poetry run pytest

Further checks

• Code is commented, particularly in hard-to-understand areas
• Tests added that prove fix is effective or that feature works

[codecov-commenter]

Codecov Report

Merging #158 (91a637a) into develop (9659a15) will increase coverage by 0.24%.
The diff coverage is 97.29%.

@@             Coverage Diff             @@
##           develop     #158      +/-   ##
===========================================
+ Coverage    94.95%   95.20%   +0.24%     
===========================================
  Files           14       14              
  Lines          714      771      +57     
===========================================
+ Hits           678      734      +56     
- Misses          36       37       +1     

Impacted Files	Coverage Δ
virtual_rainforest/core/logger.py	100.00% <ø> (ø)
virtual_rainforest/entry_points.py	75.00% <40.00%> (-7.61%)	⬇️
virtual_rainforest/core/axes.py	100.00% <100.00%> (ø)
virtual_rainforest/core/config.py	98.52% <100.00%> (+0.28%)	⬆️
virtual_rainforest/core/data.py	87.50% <100.00%> (+0.73%)	⬆️
virtual_rainforest/core/readers.py	100.00% <100.00%> (ø)
virtual_rainforest/main.py	84.00% <100.00%> (+2.46%)	⬆️
virtual_rainforest/soil/model.py	95.23% <100.00%> (+0.50%)	⬆️

📣 We’re building smart automated test selection to slash your CI/CD build times. Learn more

[jacobcook1995]

LGTM! Had a couple of pretty minor comments but generally looks good

[jacobcook1995]

should something specific be raised here (it seems to be everywhere else)?

[davidorme]

It automatically raises the except'd exception.

[jacobcook1995]

The below example doesn't actually change the exception type

[davidorme]

Huh. Good point!

[alexdewar]

This is def a cleaner approach than the log_and_raise business that came before and this PR could totally be merged as is. I do have some broader suggestions about how error handling is being done in VR though, which could be dealt with at another point.

Firstly, you're using the critical log level everywhere when it should probably be error. Critical errors are generally (I think) unrecoverable errors, but if you're re-raising an exception then it's not really unrecoverable by definition, because the caller could catch it and continue execution of the program. You could have places where you use the critical log level, but these really should be higher-level errors (e.g. "failed to load data files") at a higher level in the call stack, rather than lower-level stuff (e.g. "data file X is missing required property Y"), and it should really be the last thing you do before you terminate the program. It's fine to just call sys.exit(1) if your error really is unrecoverable.

Secondly, while it's good that you've removed the log_and_raise function, I think the general approach of "log an exception then (re-)raise it" isn't the best way to handle some of the errors you're dealing with. Let's take the validate_array function, for example. There are three places where you raise errors in this function, logging the errors before doing so. validate_array is currently only called in Data.__setitem__. To my mind, if you are going to catch and re-raise errors for this (though I'm not sure that it's necessary), it would make more sense to do it there rather than inside validate_array, e.g.:

try:
    # Validate and store the data array
    value, valid_dict = validate_dataarray(value=value, grid=self.grid)
    self.data[key] = value
    self.variable_validation[key] = valid_dict
except Exception as ex:
    LOGGER.error(f"Data validation failed: {str(ex)}")
    raise

Note that this also tells gives the user more context as to what the errors are actually about. That said, in this case, personally I would probably raise a new exception here (maybe from ex), rather than logging the error and then the caller (or the caller's caller) can decide what to do with it.

An alternative approach to explicitly logging and reraising errors everywhere would be to write a custom handler for uncaught exceptions, by overriding sys.excepthook. That way you'd only have to write this boilerplate error-handling code once, rather than every time any error happens.

In general, I'm not convinced that logging statements need to be put in the code every time an exception is raised anyway. If the exception isn't caught at any point in the call stack, then, yes, it should definitely go in your program log, but there are cleaner ways of achieving this than by having logging statements accompanying every time an error is raised (remember: DRY).* On the other hand, if an exception is caught, that kind of implies that the caller was expecting it, in which case, reporting the "error" isn't likely to be helpful anyway. Note that I'm not saying logging isn't important! For validate_dataarray for example, I would imagine that if something goes wrong in there then the program will exit 100% of the time, in which case all of those errors would percolate all of the way up the call stack and be logged anyway. The extra effort of explicitly logging these errors where they are raised is unnecessary and clutters things.

* One way is overriding sys.excepthook, as I suggested, but another way is to just wrap the entry point to your program in try/except block and do any extra handling you want to there.

[alexdewar]

I know this isn't the point of the PR, but this bit looks hacky to me.

For one thing, excep.code isn't ever going to be 0. That would indicate success, but the function will only call sys.exit() on error!

And it looks like parse_args() will print usage information anyway: https://docs.python.org/3/library/argparse.html#prog

(If the information you want isn't being displayed in case of error, it might be that you haven't supplied all the relevant options to ArgumentParser.)

Finally, if you really want to catch errors here and do something other than the default action then there is an option for it (which is cleaner than trapping calls to sys.exit): https://docs.python.org/3/library/argparse.html#exit-on-error

[davidorme]

@jacobcook1995 Have to admit that I scratched my head a bit here and then did the cosmetic change. Thoughts?

[jacobcook1995]

Weirdly, parse_args does actually raise SystemExit with an excep.code of 0, so the except block does actually print stuff.

Do agree that the information being printed is redundant though, think when I wrote this I was concerned with making sure that all information was going into LOGGER, but now realise that probably isn't a sensible concern. I think it makes sense to get rid of the whole try/except block here, as it's very hacky and doesn't print anything of use

[jacobcook1995]

Have pushed a commit removing the try/except block here

[davidorme]

That does look cleaner 😁

[alexdewar]

Is there a reason you need to declare this here?

[davidorme]

If I don't then mypy objects to me re-using to_raise because it has then acquired type ValueError. And I preferred this to to_raise_2 😄

[alexdewar]

Ohh I see. That makes sense!

[davidorme]

Lots of stuff to think on there, @alexdewar. I think you're right about where we log and trap things and as you've noted elsewhere, our logging might be getting rather verbose. I think we want verbose logging some of the time, and we probably should be using debug more. I do wonder if we might use a custom LOGGER.verbose level between debug and info.

I think we might want a bit more actually going on in the code before reviewing this, so I think we will merge but we should convert this comment to a discussion and start to flesh out a docs page on this.

One thing I had in my head wrong is the pep8 thing about over broad exceptions. I thought your example was too broad:

try:
    # Validate and store the data array
    value, valid_dict = validate_dataarray(value=value, grid=self.grid)
    self.data[key] = value
    self.variable_validation[key] = valid_dict
except Exception as ex:
    LOGGER.error(f"Data validation failed: {str(ex)}")
    raise

But no - it turns out pep8 would like a specific exception if possible but the thing it really dislikes is a bare except: (or equivalently except BaseException:) and except Exception as ex is fine.

[alexdewar]

Yeah, that sounds sensible.

I agree with the docs re the except Exception as ex bit 😄. While validate_dataarray can raise several different exception types depending on what has gone wrong (which is a sensible design), note that this particular caller doesn't need to care about the type -- it just wants to know whether or not validation was successful (though it does keep the exception's message for extra info). Distinguishing between different exception types wouldn't make sense here, because you're treating them the same.

As I said, I would probably raise a new, custom exception type here (e.g. DataError) rather than re-raising the original exception, though, then all the callers of this function can check for a single type of exception that specifically indicates that data validation failed, which is as much information as they'll need (you can pass the message of the original exception up the call stack to give extra info).