Skip to content

Logging fixes #4106

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
pp-mo merged 6 commits into from
Apr 29, 2021
Merged

Logging fixes #4106

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
37edcec
More correct use of logging.
trexfeathers Apr 22, 2021
e1f4b96
Improvements to all log unit tests.
trexfeathers Apr 22, 2021
24cbc66
CFUGRidVariable logging better integration with warn parameter.
trexfeathers Apr 23, 2021
bfbed13
Iris-specific extension to AssertLogs().
trexfeathers Apr 27, 2021
3cf6662
Simplified test_Mesh log checking.
trexfeathers Apr 27, 2021
5a997d3
Added regex convenience to Iris tests AssertLogs().
trexfeathers Apr 27, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
91 changes: 58 additions & 33 deletions lib/iris/experimental/ugrid/__init__.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@
from collections.abc import Iterable
from contextlib import contextmanager
from functools import wraps
import logging
import re
import threading

Expand Down Expand Up @@ -1229,7 +1230,7 @@ def face_dimension(self, name):
"Not setting face_dimension (inappropriate for "
f"topology_dimension={self.topology_dimension} ."
)
logger.debug(message)
logger.debug(message, extra=dict(cls=self.__class__.__name__))
elif not name or not isinstance(name, str):
face_dimension = f"Mesh{self.topology_dimension}d_face"
else:
Expand Down Expand Up @@ -3313,6 +3314,8 @@ class CFUGridConnectivityVariable(cf.CFVariable):
def identify(cls, variables, ignore=None, target=None, warn=True):
result = {}
ignore, target = cls._identify_common(variables, ignore, target)
# TODO: reconsider logging level when we have consistent practice.
log_level = logging.WARNING if warn else logging.DEBUG

# Identify all CF-UGRID connectivity variables.
for nc_var_name, nc_var in target.items():
Expand All @@ -3326,27 +3329,34 @@ def identify(cls, variables, ignore=None, target=None, warn=True):
name = nc_var_att.strip()
if name not in ignore:
if name not in variables:
if warn:
message = (
f"Missing CF-UGRID connectivity variable "
f"{name}, referenced by netCDF variable "
f"{nc_var_name}"
)
logger.debug(message)
message = (
f"Missing CF-UGRID connectivity variable "
f"{name}, referenced by netCDF variable "
f"{nc_var_name}"
)
logger.log(
level=log_level,
msg=message,
extra=dict(cls=cls.__name__),
)
else:
# Restrict to non-string type i.e. not a
# CFLabelVariable.
if not cf._is_str_dtype(variables[name]):
result[name] = CFUGridConnectivityVariable(
name, variables[name]
)
elif warn:
else:
message = (
f"Ignoring variable {name}, identified "
f"as a CF-UGRID connectivity - is a "
f"CF-netCDF label variable."
)
logger.debug(message)
logger.log(
level=log_level,
msg=message,
extra=dict(cls=cls.__name__),
)

return result

Expand Down Expand Up @@ -3385,6 +3395,8 @@ class CFUGridAuxiliaryCoordinateVariable(cf.CFVariable):
def identify(cls, variables, ignore=None, target=None, warn=True):
result = {}
ignore, target = cls._identify_common(variables, ignore, target)
# TODO: reconsider logging level when we have consistent practice.
log_level = logging.WARNING if warn else logging.DEBUG

# Identify any CF-UGRID-relevant auxiliary coordinate variables.
for nc_var_name, nc_var in target.items():
Expand All @@ -3396,14 +3408,16 @@ def identify(cls, variables, ignore=None, target=None, warn=True):
for name in nc_var_att.split():
if name not in ignore:
if name not in variables:
if warn:
message = (
f"Missing CF-netCDF auxiliary "
f"coordinate variable {name}, "
f"referenced by netCDF variable "
f"{nc_var_name}"
)
logger.debug(message)
message = (
f"Missing CF-netCDF auxiliary coordinate "
f"variable {name}, referenced by netCDF "
f"variable {nc_var_name}"
)
logger.log(
level=log_level,
msg=message,
extra=dict(cls=cls.__name__),
)
else:
# Restrict to non-string type i.e. not a
# CFLabelVariable.
Expand All @@ -3413,14 +3427,18 @@ def identify(cls, variables, ignore=None, target=None, warn=True):
] = CFUGridAuxiliaryCoordinateVariable(
name, variables[name]
)
elif warn:
else:
message = (
f"Ignoring variable {name}, "
f"identified as a CF-netCDF auxiliary "
f"coordinate - is a CF-netCDF label "
f"variable."
f"identified as a CF-netCDF "
f"auxiliary coordinate - is a "
f"CF-netCDF label variable."
)
logger.log(
level=log_level,
msg=message,
extra=dict(cls=cls.__name__),
)
logger.debug(message)

return result

Expand Down Expand Up @@ -3451,6 +3469,8 @@ class CFUGridMeshVariable(cf.CFVariable):
def identify(cls, variables, ignore=None, target=None, warn=True):
result = {}
ignore, target = cls._identify_common(variables, ignore, target)
# TODO: reconsider logging level when we have consistent practice.
log_level = logging.WARNING if warn else logging.DEBUG

# Identify all CF-UGRID mesh variables.
for nc_var_name, nc_var in target.items():
Expand All @@ -3462,26 +3482,33 @@ def identify(cls, variables, ignore=None, target=None, warn=True):
name = nc_var_att.strip()
if name not in ignore:
if name not in variables:
if warn:
message = (
f"Missing CF-UGRID mesh variable {name}, "
f"referenced by netCDF variable {nc_var_name}"
)
logger.debug(message)
message = (
f"Missing CF-UGRID mesh variable {name}, "
f"referenced by netCDF variable {nc_var_name}"
)
logger.log(
level=log_level,
msg=message,
extra=dict(cls=cls.__name__),
)
else:
# Restrict to non-string type i.e. not a
# CFLabelVariable.
if not cf._is_str_dtype(variables[name]):
result[name] = CFUGridMeshVariable(
name, variables[name]
)
elif warn:
else:
message = (
f"Ignoring variable {name}, identified as a "
f"CF-UGRID mesh - is a CF-netCDF label "
f"variable."
)
logger.debug(message)
logger.log(
level=log_level,
msg=message,
extra=dict(cls=cls.__name__),
)

return result

Expand Down Expand Up @@ -3673,7 +3700,6 @@ def _build_mesh(cf, mesh_var, file_path):
", consistent with the attached connectivities."
)
# TODO: reconsider logging level when we have consistent practice.
# TODO: logger always requires extras['cls'] : can we fix this?
logger.warning(msg, extra=dict(cls=None))
else:
quoted_topology_dimension = mesh_var.topology_dimension
Expand All @@ -3687,7 +3713,6 @@ def _build_mesh(cf, mesh_var, file_path):
" -- ignoring this as it is inconsistent."
)
# TODO: reconsider logging level when we have consistent practice.
# TODO: logger always requires extras['cls'] : can we fix this?
logger.warning(msg=msg, extra=dict(cls=None))

node_dimension = None
Expand Down
2 changes: 1 addition & 1 deletion lib/iris/fileformats/netcdf.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -52,7 +52,7 @@
DEBUG = False

# Configure the logger.
logger = iris.config.get_logger(__name__, fmt="[%(cls)s.%(funcName)s]")
logger = iris.config.get_logger(__name__)

# Pyke CF related file names.
_PYKE_RULE_BASE = "fc_rules_cf"
Expand Down
36 changes: 36 additions & 0 deletions lib/iris/tests/__init__.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -607,6 +607,42 @@ def assertWarnsRegexp(self, expected_regexp=""):
msg = msg.format(expected_regexp)
self.assertTrue(matches, msg)

@contextlib.contextmanager
def assertLogs(self, logger=None, level=None, msg_regex=None):
"""
An extended version of the usual :meth:`unittest.TestCase.assertLogs`,
which also exercises the logger's message formatting.

Also adds the ``msg_regex`` kwarg:
If used, check that the result is a single message of the specified
level, and that it matches this regex.

The inherited version of this method temporarily *replaces* the logger
in order to capture log records generated within the context.
However, in doing so it prevents any messages from being formatted
by the original logger.
This version first calls the original method, but then *also* exercises
the message formatters of all the logger's handlers, just to check that
there are no formatting errors.

"""
# Invoke the standard assertLogs behaviour.
assertlogging_context = super().assertLogs(logger, level)
with assertlogging_context as watcher:
# Run the caller context, as per original method.
yield watcher
# Check for any formatting errors by running all the formatters.
for record in watcher.records:
for handler in assertlogging_context.logger.handlers:
handler.format(record)

# Check message, if requested.
if msg_regex:
self.assertEqual(len(watcher.records), 1)
rec = watcher.records[0]
self.assertEqual(level, rec.levelname)
self.assertRegex(rec.msg, msg_regex)

@contextlib.contextmanager
def assertNoWarningsRegexp(self, expected_regexp=""):
# Check that no warning matching the given expression is raised.
Expand Down
18 changes: 4 additions & 14 deletions lib/iris/tests/integration/experimental/test_ugrid_load.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -155,36 +155,26 @@ def create_synthetic_file(self, **create_kwargs):

def test_mesh_bad_topology_dimension(self):
# Check that the load generates a suitable warning.
with self.assertLogs(logger) as log:
log_regex = r"topology_dimension.* ignoring"
with self.assertLogs(logger, level="WARNING", msg_regex=log_regex):
template = "minimal_bad_topology_dim"
dim_line = "mesh_var:topology_dimension = 1 ;" # which is wrong !
cube = self.create_synthetic_test_cube(
template=template, subs=dict(TOPOLOGY_DIM_DEFINITION=dim_line)
)
# Check we got just one message, and its content
self.assertEqual(len(log.records), 1)
rec = log.records[0]
self.assertEqual(rec.levelname, "WARNING")
re_msg = r"topology_dimension.* ignoring"
self.assertRegex(rec.msg, re_msg)

# Check that the result has topology-dimension of 2 (not 1).
self.assertEqual(cube.mesh.topology_dimension, 2)

def test_mesh_no_topology_dimension(self):
# Check that the load generates a suitable warning.
with self.assertLogs(logger) as log:
log_regex = r"Mesh variable.* has no 'topology_dimension'"
with self.assertLogs(logger, level="WARNING", msg_regex=log_regex):
template = "minimal_bad_topology_dim"
dim_line = "" # don't create ANY topology_dimension property
cube = self.create_synthetic_test_cube(
template=template, subs=dict(TOPOLOGY_DIM_DEFINITION=dim_line)
)
# Check we got just one message, and its content
self.assertEqual(len(log.records), 1)
rec = log.records[0]
self.assertEqual(rec.levelname, "WARNING")
re_msg = r"Mesh variable.* has no 'topology_dimension'"
self.assertRegex(rec.msg, re_msg)

# Check that the result has the correct topology-dimension value.
self.assertEqual(cube.mesh.topology_dimension, 2)
Expand Down
47 changes: 20 additions & 27 deletions lib/iris/tests/unit/experimental/ugrid/test_CFUGridAuxiliaryCoordinateVariable.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -213,33 +213,26 @@ def test_warn(self):
"ref_source": ref_source,
}

# Missing warning.
with self.assertLogs(logger, level="DEBUG") as log:
result = CFUGridAuxiliaryCoordinateVariable.identify(
vars_all, warn=False
)
self.assertEqual(0, len(log.output))
self.assertDictEqual({}, result)
# The warn kwarg and expected corresponding log level.
warn_and_level = {True: "WARNING", False: "DEBUG"}

# Default is warn=True
result = CFUGridAuxiliaryCoordinateVariable.identify(vars_all)
self.assertIn(
f"Missing CF-netCDF auxiliary coordinate variable {subject_name}",
log.output[0],
)
self.assertDictEqual({}, result)
# Missing warning.
log_regex = rf"Missing CF-netCDF auxiliary coordinate variable {subject_name}.*"
for warn, level in warn_and_level.items():
with self.assertLogs(logger, level=level, msg_regex=log_regex):
result = CFUGridAuxiliaryCoordinateVariable.identify(
vars_all, warn=warn
)
self.assertDictEqual({}, result)

# String variable warning.
with self.assertLogs(logger, level="DEBUG") as log:
vars_all[subject_name] = netcdf_ugrid_variable(
subject_name, "", np.bytes_
)
result = CFUGridAuxiliaryCoordinateVariable.identify(
vars_all, warn=False
)
self.assertDictEqual({}, result)

# Default is warn=True
result = CFUGridAuxiliaryCoordinateVariable.identify(vars_all)
self.assertIn("is a CF-netCDF label variable", log.output[0])
self.assertDictEqual({}, result)
log_regex = r".*is a CF-netCDF label variable.*"
for warn, level in warn_and_level.items():
with self.assertLogs(logger, level=level, msg_regex=log_regex):
vars_all[subject_name] = netcdf_ugrid_variable(
subject_name, "", np.bytes_
)
result = CFUGridAuxiliaryCoordinateVariable.identify(
vars_all, warn=warn
)
self.assertDictEqual({}, result)
43 changes: 20 additions & 23 deletions lib/iris/tests/unit/experimental/ugrid/test_CFUGridConnectivityVariable.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -202,29 +202,26 @@ def test_warn(self):
"ref_source": ref_source,
}

# Missing warning.
with self.assertLogs(logger, level="DEBUG") as log:
result = CFUGridConnectivityVariable.identify(vars_all, warn=False)
self.assertEqual(0, len(log.output))
self.assertDictEqual({}, result)
# The warn kwarg and expected corresponding log level.
warn_and_level = {True: "WARNING", False: "DEBUG"}

# Default is warn=True
result = CFUGridConnectivityVariable.identify(vars_all)
self.assertIn(
f"Missing CF-UGRID connectivity variable {subject_name}",
log.output[0],
)
self.assertDictEqual({}, result)
# Missing warning.
log_regex = rf"Missing CF-UGRID connectivity variable {subject_name}.*"
for warn, level in warn_and_level.items():
with self.assertLogs(logger, level=level, msg_regex=log_regex):
result = CFUGridConnectivityVariable.identify(
vars_all, warn=warn
)
self.assertDictEqual({}, result)

# String variable warning.
with self.assertLogs(logger, level="DEBUG") as log:
vars_all[subject_name] = netcdf_ugrid_variable(
subject_name, "", np.bytes_
)
result = CFUGridConnectivityVariable.identify(vars_all, warn=False)
self.assertDictEqual({}, result)

# Default is warn=True
result = CFUGridConnectivityVariable.identify(vars_all)
self.assertIn("is a CF-netCDF label variable", log.output[0])
self.assertDictEqual({}, result)
log_regex = r".*is a CF-netCDF label variable.*"
for warn, level in warn_and_level.items():
with self.assertLogs(logger, level=level, msg_regex=log_regex):
vars_all[subject_name] = netcdf_ugrid_variable(
subject_name, "", np.bytes_
)
result = CFUGridConnectivityVariable.identify(
vars_all, warn=warn
)
self.assertDictEqual({}, result)
Loading