iris
iris copied to clipboard
Adopt logging
Silence the noise of iris
warnings through logging
and provide clear guidance to developers on the use of logging
and associated logging
levels, and when it is actually appropriate to use warnings
in the Iris developers guide.
Reference:
Enabled by #3785 and the inclusion of iris.config.get_logger
This came up in a dev discussion this morning. Having started to use logging around Iris, we would like to collectively agree on exactly how we will use it.
Relevant concerns
- Using Iris is currently noisy with many warnings.
- Feedback indicates this is irritating users.
-
As already stated: switching from
warnings.warn()
to logging is an opportunity to 'quieten' the noise.
- So far only using logging's
DEBUG
level - not always appropriate.-
According to the Python docs: the
WARNING
level should be used when "something unexpected happened". -
DEBUG
should be used for "Detailed information, typically of interest only when diagnosing problems" - it's information on what's happening, in case it might be relevant. As opposed to something we already know is problematic. -
1 example where
WARNING
level would be more appropriate. - By default, using the
WARNING
level results in output tostderr
, so keeping Iris quiet would need raising of thelogger
's 'level'.
-
According to the Python docs: the
- Very difficult to know when warnings are helpful and when they are irritating.
- Logging items above or below the
logger
's set level is very all-or-nothing in this regard. - Our current experience suggests that users who want the extra information may not be satisfied with being told they can optionally interrogate the log. Users have always been able to optionally filter/suppress warnings, but we still receive irritated feedback at the standard behaviour.
- Logging items above or below the
My two cents
- Totally in favour of wholesale switching to logging. Logging offers the opportunity to record new helpful events, and to better structure recording events in general.
- Convert
warnings.warn()
tologger.warning()
. From a Pythonic perspective we're already using the correct level. - Raise our
logger
's level to makeWARNING
silent at the command line. Pythonic or not, the volume of warnings is known to be unhelpful to many users. - Modify our
logger
to raise a standardwarnings.warn()
if anyWARNING
s are recorded in the log.- The identical nature means that only one warning will be seen at the command line, no matter how many different
WARNING
s are being logged. - Keeps the user informed that something in the log may need their attention, without the noisy output.
- Fairly certain this would unfortunately preclude the simple use of
logging.captureWarnings()
, instead requiring us to actually convertwarnings.warn()
tologger.warning()
but it would be worth it IMO. - I think this could be achieved by replacing the current
StreamHandler
with one that has a modifiedemit()
method, but there may be a better way.
- The identical nature means that only one warning will be seen at the command line, no matter how many different
Bumped into this while working on #4099
I'm concerned that the newer code in iris.experimental.ugrid
is logging what in some case "should" be warnings (IMHO) as debug,
e.g. here
From the logging module description of levels, I think we should be using 'warning' when we discover and/or workaround something that "should not happen". As it is stated there : "WARNING : An indication that something unexpected happened, or indicative of some problem in the near future (e.g. ‘disk space low’). The software is still working as expected.".
The bottom line for me is that we should not be totally silent, when working around things which are actually "wrong" : And especially in the case just investigated, when an input file is formatted incorrectly, and we are making the best of it. We shouldn't let defensive programming result in "hiding" problems from the user.
But I do agree with @trexfeathers that we could maybe engineer a default behaviour that emits a one-time message "that warning-level events have occurred".
Other thoughts:
- the logging module can automatically capture all warnings output.
So maybe we use that to avoid changing lots of existing source ? - (however) the warnings approach allows to classify / filter warnings by Exception subclassing, and labels messages according to the source line / callstack. I'm not sure if we will be missing some of that functionality? However, by enabling us to hide things + record them elsewhere, the logging module maybe makes all this much less necessary
- the existing warnings (notably for netcdf loading) don't seem to doing the desired 'show once only' behaviour, and I'm not sure why not. Probably ok, when ported to logging, as in previous point
- it would still be really good to include source line / stacktrace type info, which we are getting free with 'warnings', but not with 'logging' unless it is an exception. Without that, some of the existing messages are probably going to be a bit useless. This detail info is anyway less obtrusive if we're not putting it to the console by default.
Additional note : unfinished business / tech-debt
From my experience on #4099 I am now suspicious of most of the existing usage of 'logger' in the ugrid code.
It seems to be obligatory for any logger.log
usage to add an "extra=dict(cls=
I think this is simply due to the way the "iris.experimental.ugrid" logger is created / defined
So, I think a lot of the existing calls don't have this + may be bugged. Within existing code, I found:
- https://github.com/SciTools/iris/blob/1ed885e9ffb167d4e5b9b5908d3f763703366f2d/lib/iris/experimental/ugrid/init.py#L1232
- https://github.com/SciTools/iris/blob/1ed885e9ffb167d4e5b9b5908d3f763703366f2d/lib/iris/experimental/ugrid/init.py#L3335
- https://github.com/SciTools/iris/blob/1ed885e9ffb167d4e5b9b5908d3f763703366f2d/lib/iris/experimental/ugrid/init.py#L3349
- https://github.com/SciTools/iris/blob/1ed885e9ffb167d4e5b9b5908d3f763703366f2d/lib/iris/experimental/ugrid/init.py#L3406
- https://github.com/SciTools/iris/blob/1ed885e9ffb167d4e5b9b5908d3f763703366f2d/lib/iris/experimental/ugrid/init.py#L3423
- https://github.com/SciTools/iris/blob/1ed885e9ffb167d4e5b9b5908d3f763703366f2d/lib/iris/experimental/ugrid/init.py#L3470
- https://github.com/SciTools/iris/blob/1ed885e9ffb167d4e5b9b5908d3f763703366f2d/lib/iris/experimental/ugrid/init.py#L3484
Unfortunately I'm not just fixing these now, as I think to do that we should really add tests for these code sections -- so it's not just a quickie (!)
EDIT: my mistake for taking inspiration from metadata.py rather than the other two examples. I will try to fix this in due course. Sorry.
I think a lot of the existing calls don't have this + may be bugged.
@pp-mo I'm struggling to see how this could be the case.
- All those instances are unit tested for log entries.
-
There's also the fact that logging is already part of core Iris code, and doesn't always provide the
extra
kwarg. Examples:- https://github.com/SciTools/iris/blob/98baee21721826a2a3c25d9169ed7e97e16e5e12/lib/iris/common/resolve.py#L352
- https://github.com/SciTools/iris/blob/98baee21721826a2a3c25d9169ed7e97e16e5e12/lib/iris/common/resolve.py#L394
- https://github.com/SciTools/iris/blob/98baee21721826a2a3c25d9169ed7e97e16e5e12/lib/iris/analysis/maths.py#L704
- https://github.com/SciTools/iris/blob/98baee21721826a2a3c25d9169ed7e97e16e5e12/lib/iris/analysis/maths.py#L1122
There's also the fact that logging is already part of core Iris code, and doesn't always provide the extra kwarg.
I think my point only applies to the ones in iris.experimental.ugrid
.
Both iris.common.resolve
and iris.common.maths
have their own loggers which are configured differently, e.g. the one in resolve.py.
Whereas, in iris.common.metadata
, its logger is defined in the same way as in experimental.ugrid, but all the calls there use the 'extra' keyword like this.
All those instances are unit tested for log entries.
After some effort, I worked this out. Unfortunately, it's a bit horrible ...
The testing code is replacing the real logger with the one used to record logging in the test, so the 'real' one is not actually called.
E.G. looking at this test.
So, in that test, I added another self.mesh.dimension_names("foo", "bar", "baz")
before the logging test context.
That still didn't get an error, because the default level is wrong (> 'DEBUG'), so it isn't logging the message
But when I also add a line to set the level, I do get the error...
Test code now :
def test_dimension_names(self):
# Test defaults.
default = ugrid.Mesh1DNames("Mesh1d_node", "Mesh1d_edge")
self.assertEqual(default, self.mesh.dimension_names())
// ADDED LINES
ugrid.logger.setLevel('DEBUG')
self.mesh.dimension_names("foo", "bar", "baz")
// END ADDED LINES
with self.assertLogs(ugrid.logger, level="DEBUG") as log:
self.mesh.dimension_names("foo", "bar", "baz")
self.assertIn("Not setting face_dimension", log.output[0])
. . .
Now I do get the expected error when I run the test.
$ python -m unittest iris.tests.unit.experimental.ugrid.test_Mesh
.............--- Logging error ---
Traceback (most recent call last):
File "/tmp/persistent/miniconda3/envs/irisgrib/lib/python3.7/logging/__init__.py", line 1025, in emit
msg = self.format(record)
File "/tmp/persistent/miniconda3/envs/irisgrib/lib/python3.7/logging/__init__.py", line 869, in format
return fmt.format(record)
File "/tmp/persistent/miniconda3/envs/irisgrib/lib/python3.7/logging/__init__.py", line 611, in format
s = self.formatMessage(record)
File "/tmp/persistent/miniconda3/envs/irisgrib/lib/python3.7/logging/__init__.py", line 580, in formatMessage
return self._style.format(record)
File "/tmp/persistent/miniconda3/envs/irisgrib/lib/python3.7/logging/__init__.py", line 422, in format
return self._fmt % record.__dict__
KeyError: 'cls'
Call stack:
. . .
Afterthought ... As you said, all the logging instances are all debugged, so I was really wrong about needing to add more testing.
In that case, that should make it pretty easy to fix this after all, and ensure that the tests are fully exercising the code. E.G. we can maybe work out a way to test via the existing per-module loggers, rather than replacing them ? I still think it's a separate operation though : the decisions aren't totally trivial.
I think we should draw this discussion to a close here on this issue.
Remember that we do now have GitHub Discussions which might be more appropriate.
Nevertheless, I'll draft an IEP to cover this. Which will promote a more concise and transparent summary of what's been proposed and how this should be applied with iris 👍
Ping @Knight
Somewhat related, re improving tests of logging usage : https://github.com/SciTools/iris/pull/4106
Uncertainty at this point makes this issue inappropriate for a release - needs internal discussion
From @jamesp:
Logging is a different use case to warning. Logging is about recording information of the activity of a system, typically an event-based system, for review later. Iris is a library, not a system. everything is deterministic in Iris. It could be appropriate for systems using Iris to employ logging, but not within Iris itself.
Also, what is the mechanism for, in code, dealing with things you put in logs? If you use warnings, I think developers can catch that in an if statement.
In conversation, we agreed that any time that Iris' behaviour deserves communication to the user should either be a Warning
or an Exception
. There is no case for providing the user with DEBUG
or INFO
level information.
If we better categorise Iris' warnings, we can then educate the user base on catching the categories they are comfortable ignoring. We could also provide one or more conveniences for opting out of some/all Iris warnings.
It seems like the main part of solving Iris' verbosity is user education. This would also be needed with any logging-based solution.
There is of course a separate argument for implementing logging to aid Iris development. But that was not the original scope of this issue:
Silence the noise of
iris
warnings throughlogging
...
In a peloton meeting, @bsherratt clarified a couple of technical points :
- warnings do not have a built-in "severity level" -- though a class hierarchy could be used (in Iris) to provide multi-level control
- logging allows building a hierarchy of loggers to control messages/recording in different specific areas, such a specific sub-modules (some of this is already anticipated in existing code)
- logging doesn't really provide simple general-purpose control and reporting methods.
Whether warnings or logging, we should provide Iris-specific control mechanism which are easy to use.
https://github.com/Delgan/loguru is a thing.
Perhaps relevant, perhaps not.
Closing due to recent progress:
- Decided as a team that we want to work with Python's warnings filter, so using warnings rather than logging where warnings are needed - #5474
- Part of Iris' verbosity is due to duplicated warnings. We have made lots of progress understanding the cause of these, but still need work to prevent them - #5464
- Remaining use of logging for debugging purposes is of speculative value, so is at best low priority. #5518