Adopt logging -- or something?

[bjlittle]

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:

• PR 3139
• Issue 3078

[bjlittle]

Enabled by #3785 and the inclusion of iris.config.get_logger

[trexfeathers]

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 to stderr, so keeping Iris quiet would need raising of the logger's 'level'.
• 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.

[trexfeathers]

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() to logger.warning().
  From a Pythonic perspective we're already using the correct level.
• Raise our logger's level to make WARNING 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 standard warnings.warn() if any WARNINGs 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 WARNINGs 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 convert warnings.warn() to logger.warning() but it would be worth it IMO.
  • I think this could be achieved by replacing the current StreamHandler with one that has a modified emit() method, but there may be a better way.

[pp-mo]

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.

[pp-mo]

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=)`, otherwise you get a runtime error when the logging code is actually called.
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:

• iris/lib/iris/experimental/ugrid/__init__.py

  Line 1232 in 1ed885e

  logger.debug(message)

• iris/lib/iris/experimental/ugrid/__init__.py

  Line 3335 in 1ed885e

  logger.debug(message)

• iris/lib/iris/experimental/ugrid/__init__.py

  Line 3349 in 1ed885e

  logger.debug(message)

• iris/lib/iris/experimental/ugrid/__init__.py

  Line 3406 in 1ed885e

  logger.debug(message)

• iris/lib/iris/experimental/ugrid/__init__.py

  Line 3423 in 1ed885e

  logger.debug(message)

• iris/lib/iris/experimental/ugrid/__init__.py

  Line 3470 in 1ed885e

  logger.debug(message)

• iris/lib/iris/experimental/ugrid/__init__.py

  Line 3484 in 1ed885e

  logger.debug(message)

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 (!)

[trexfeathers]

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.

1. All those instances are unit tested for log entries.
2. There's also the fact that logging is already part of core Iris code, and doesn't always provide the extra kwarg.
   Examples:

   • iris/lib/iris/common/resolve.py

     Line 352 in 98baee2

     logger.debug(f"map_rhs_to_lhs={self.map_rhs_to_lhs}")

   • iris/lib/iris/common/resolve.py

     Line 394 in 98baee2

     logger.debug(dmsg)

   • iris/lib/iris/analysis/maths.py

     Line 704 in 98baee2

     logger.debug(dmsg)

   • iris/lib/iris/analysis/maths.py

     Line 1122 in 98baee2

     logger.debug(dmsg)

[pp-mo]

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.

[pp-mo]

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:
 . . .

[pp-mo]

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.

[bjlittle]

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

[pp-mo]

Somewhat related, re improving tests of logging usage : #4106