Skip to content
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

Logging fixes #4106

Merged
merged 6 commits into from
Apr 29, 2021
+181 −142
Merged

Logging fixes #4106

Show file tree
Hide file tree
Changes from 5 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
25 changes: 25 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,31 @@ def assertWarnsRegexp(self, expected_regexp=""):
msg = msg.format(expected_regexp)
self.assertTrue(matches, msg)

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

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)

@contextlib.contextmanager
def assertNoWarningsRegexp(self, expected_regexp=""):
# Check that no warning matching the given expression is raised.
Expand Down
19 changes: 13 additions & 6 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,40 @@ def test_warn(self):
"ref_source": ref_source,
}

def check_log(expected_levelname, log_regex):
rec = log.records[-1]
self.assertEqual(expected_levelname, rec.levelname)
self.assertRegex(rec.msg, log_regex)

# Missing warning.
with self.assertLogs(logger, level="DEBUG") as log:
log_regex = rf"Missing CF-netCDF auxiliary coordinate variable {subject_name}.*"

result = CFUGridAuxiliaryCoordinateVariable.identify(
vars_all, warn=False
)
self.assertEqual(0, len(log.output))
check_log("DEBUG", log_regex)
self.assertDictEqual({}, result)

# Default is warn=True
result = CFUGridAuxiliaryCoordinateVariable.identify(vars_all)
self.assertIn(
f"Missing CF-netCDF auxiliary coordinate variable {subject_name}",
log.output[0],
)
check_log("WARNING", log_regex)
self.assertDictEqual({}, result)

# String variable warning.
with self.assertLogs(logger, level="DEBUG") as log:
log_regex = r".*is a CF-netCDF label variable.*"
vars_all[subject_name] = netcdf_ugrid_variable(
subject_name, "", np.bytes_
)

result = CFUGridAuxiliaryCoordinateVariable.identify(
vars_all, warn=False
)
check_log("DEBUG", log_regex)
self.assertDictEqual({}, result)

# Default is warn=True
result = CFUGridAuxiliaryCoordinateVariable.identify(vars_all)
self.assertIn("is a CF-netCDF label variable", log.output[0])
check_log("WARNING", log_regex)
self.assertDictEqual({}, result)
21 changes: 15 additions & 6 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,38 @@ def test_warn(self):
"ref_source": ref_source,
}

def check_log(expected_levelname, log_regex):
rec = log.records[-1]
self.assertEqual(expected_levelname, rec.levelname)
self.assertRegex(rec.msg, log_regex)

# Missing warning.
with self.assertLogs(logger, level="DEBUG") as log:
log_regex = (
rf"Missing CF-UGRID connectivity variable {subject_name}.*"
)

result = CFUGridConnectivityVariable.identify(vars_all, warn=False)
self.assertEqual(0, len(log.output))
check_log("DEBUG", log_regex)
self.assertDictEqual({}, result)

# Default is warn=True
result = CFUGridConnectivityVariable.identify(vars_all)
self.assertIn(
f"Missing CF-UGRID connectivity variable {subject_name}",
log.output[0],
)
check_log("WARNING", log_regex)
self.assertDictEqual({}, result)

# String variable warning.
with self.assertLogs(logger, level="DEBUG") as log:
log_regex = r".*is a CF-netCDF label variable.*"
vars_all[subject_name] = netcdf_ugrid_variable(
subject_name, "", np.bytes_
)

result = CFUGridConnectivityVariable.identify(vars_all, warn=False)
check_log("DEBUG", log_regex)
self.assertDictEqual({}, result)

# Default is warn=True
result = CFUGridConnectivityVariable.identify(vars_all)
self.assertIn("is a CF-netCDF label variable", log.output[0])
check_log("WARNING", log_regex)
self.assertDictEqual({}, result)
18 changes: 13 additions & 5 deletions lib/iris/tests/unit/experimental/ugrid/test_CFUGridMeshVariable.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -195,28 +195,36 @@ def test_warn(self):
"ref_source": ref_source,
}

def check_log(expected_levelname, log_regex):
rec = log.records[-1]
self.assertEqual(expected_levelname, rec.levelname)
self.assertRegex(rec.msg, log_regex)

# Missing warning.
with self.assertLogs(logger, level="DEBUG") as log:
log_regex = rf"Missing CF-UGRID mesh variable {subject_name}.*"

result = CFUGridMeshVariable.identify(vars_all, warn=False)
self.assertEqual(0, len(log.output))
check_log("DEBUG", log_regex)
self.assertDictEqual({}, result)

# Default is warn=True
result = CFUGridMeshVariable.identify(vars_all)
self.assertIn(
f"Missing CF-UGRID mesh variable {subject_name}", log.output[0]
)
check_log("WARNING", log_regex)
self.assertDictEqual({}, result)

# String variable warning.
with self.assertLogs(logger, level="DEBUG") as log:
log_regex = r".*is a CF-netCDF label variable.*"
vars_all[subject_name] = netcdf_ugrid_variable(
subject_name, "", np.bytes_
)

result = CFUGridMeshVariable.identify(vars_all, warn=False)
check_log("DEBUG", log_regex)
self.assertDictEqual({}, result)

# Default is warn=True
result = CFUGridMeshVariable.identify(vars_all)
self.assertIn("is a CF-netCDF label variable", log.output[0])
check_log("WARNING", log_regex)
self.assertDictEqual({}, result)
Loading