diff --git a/lib/iris/experimental/ugrid/__init__.py b/lib/iris/experimental/ugrid/__init__.py index b0f0d8c533..8eefedb6ea 100644 --- a/lib/iris/experimental/ugrid/__init__.py +++ b/lib/iris/experimental/ugrid/__init__.py @@ -15,6 +15,7 @@ from collections.abc import Iterable from contextlib import contextmanager from functools import wraps +import logging import re import threading @@ -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: @@ -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(): @@ -3326,13 +3329,16 @@ 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. @@ -3340,13 +3346,17 @@ def identify(cls, variables, ignore=None, target=None, warn=True): 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 @@ -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(): @@ -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. @@ -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 @@ -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(): @@ -3462,12 +3482,15 @@ 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. @@ -3475,13 +3498,17 @@ def identify(cls, variables, ignore=None, target=None, warn=True): 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 @@ -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 @@ -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 diff --git a/lib/iris/fileformats/netcdf.py b/lib/iris/fileformats/netcdf.py index 5486c3a9db..00a207b86d 100644 --- a/lib/iris/fileformats/netcdf.py +++ b/lib/iris/fileformats/netcdf.py @@ -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" diff --git a/lib/iris/tests/__init__.py b/lib/iris/tests/__init__.py index b2eebc4f03..7c7adf12ce 100644 --- a/lib/iris/tests/__init__.py +++ b/lib/iris/tests/__init__.py @@ -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. diff --git a/lib/iris/tests/integration/experimental/test_ugrid_load.py b/lib/iris/tests/integration/experimental/test_ugrid_load.py index aa73103130..6886418fb6 100644 --- a/lib/iris/tests/integration/experimental/test_ugrid_load.py +++ b/lib/iris/tests/integration/experimental/test_ugrid_load.py @@ -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) diff --git a/lib/iris/tests/unit/experimental/ugrid/test_CFUGridAuxiliaryCoordinateVariable.py b/lib/iris/tests/unit/experimental/ugrid/test_CFUGridAuxiliaryCoordinateVariable.py index a0e5c5e3f2..bb593dc25e 100644 --- a/lib/iris/tests/unit/experimental/ugrid/test_CFUGridAuxiliaryCoordinateVariable.py +++ b/lib/iris/tests/unit/experimental/ugrid/test_CFUGridAuxiliaryCoordinateVariable.py @@ -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) diff --git a/lib/iris/tests/unit/experimental/ugrid/test_CFUGridConnectivityVariable.py b/lib/iris/tests/unit/experimental/ugrid/test_CFUGridConnectivityVariable.py index 5cf40026cb..d24870c49b 100644 --- a/lib/iris/tests/unit/experimental/ugrid/test_CFUGridConnectivityVariable.py +++ b/lib/iris/tests/unit/experimental/ugrid/test_CFUGridConnectivityVariable.py @@ -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) diff --git a/lib/iris/tests/unit/experimental/ugrid/test_CFUGridMeshVariable.py b/lib/iris/tests/unit/experimental/ugrid/test_CFUGridMeshVariable.py index 79601b8604..b89a341ccc 100644 --- a/lib/iris/tests/unit/experimental/ugrid/test_CFUGridMeshVariable.py +++ b/lib/iris/tests/unit/experimental/ugrid/test_CFUGridMeshVariable.py @@ -195,28 +195,22 @@ def test_warn(self): "ref_source": ref_source, } + # The warn kwarg and expected corresponding log level. + warn_and_level = {True: "WARNING", False: "DEBUG"} + # Missing warning. - with self.assertLogs(logger, level="DEBUG") as log: - result = CFUGridMeshVariable.identify(vars_all, warn=False) - self.assertEqual(0, len(log.output)) - 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] - ) - self.assertDictEqual({}, result) + log_regex = rf"Missing CF-UGRID mesh variable {subject_name}.*" + for warn, level in warn_and_level.items(): + with self.assertLogs(logger, level=level, msg_regex=log_regex): + result = CFUGridMeshVariable.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 = CFUGridMeshVariable.identify(vars_all, warn=False) - self.assertDictEqual({}, result) - - # Default is warn=True - result = CFUGridMeshVariable.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 = CFUGridMeshVariable.identify(vars_all, warn=warn) + self.assertDictEqual({}, result) diff --git a/lib/iris/tests/unit/experimental/ugrid/test_Mesh.py b/lib/iris/tests/unit/experimental/ugrid/test_Mesh.py index 9848809206..fa118ec082 100644 --- a/lib/iris/tests/unit/experimental/ugrid/test_Mesh.py +++ b/lib/iris/tests/unit/experimental/ugrid/test_Mesh.py @@ -192,9 +192,9 @@ def test_connectivities_locations(self): for kwargs in negative_kwargs: self.assertEqual([], func(**kwargs)) - with self.assertLogs(ugrid.logger, level="DEBUG") as log: + log_regex = r".*filter for non-existent.*" + with self.assertLogs(ugrid.logger, level="DEBUG", msg_regex=log_regex): self.assertEqual([], func(contains_face=True)) - self.assertIn("filter for non-existent", log.output[0]) def test_coord(self): # See Mesh.coords tests for thorough coverage of cases. @@ -264,9 +264,9 @@ def test_coords_locations(self): expected = [all_expected[k] for k in expected if k in all_expected] self.assertEqual(expected, func(**kwargs)) - with self.assertLogs(ugrid.logger, level="DEBUG") as log: + log_regex = r".*filter non-existent.*" + with self.assertLogs(ugrid.logger, level="DEBUG", msg_regex=log_regex): self.assertEqual([], func(include_faces=True)) - self.assertIn("filter non-existent", log.output[0]) def test_edge_dimension(self): self.assertEqual( @@ -618,9 +618,9 @@ def test_add_connectivities_invalid(self): ) face_node = self.FACE_NODE - with self.assertLogs(ugrid.logger, level="DEBUG") as log: + log_regex = r"Not adding connectivity.*" + with self.assertLogs(ugrid.logger, level="DEBUG", msg_regex=log_regex): self.mesh.add_connectivities(face_node) - self.assertIn("Not adding connectivity", log.output[0]) def test_add_coords(self): # ADD coords. @@ -725,9 +725,9 @@ def test_dimension_names(self): default = ugrid.Mesh1DNames("Mesh1d_node", "Mesh1d_edge") self.assertEqual(default, self.mesh.dimension_names()) - with self.assertLogs(ugrid.logger, level="DEBUG") as log: + log_regex = r"Not setting face_dimension.*" + with self.assertLogs(ugrid.logger, level="DEBUG", msg_regex=log_regex): self.mesh.dimension_names("foo", "bar", "baz") - self.assertIn("Not setting face_dimension", log.output[0]) self.assertEqual( ugrid.Mesh1DNames("foo", "bar"), self.mesh.dimension_names() ) @@ -746,9 +746,9 @@ def test_edge_dimension_set(self): self.assertEqual("foo", self.mesh.edge_dimension) def test_face_dimension_set(self): - with self.assertLogs(ugrid.logger, level="DEBUG") as log: + log_regex = r"Not setting face_dimension.*" + with self.assertLogs(ugrid.logger, level="DEBUG", msg_regex=log_regex): self.mesh.face_dimension = "foo" - self.assertIn("Not setting face_dimension", log.output[0]) self.assertIsNone(self.mesh.face_dimension) def test_node_dimension_set(self): @@ -790,17 +790,19 @@ def test_remove_connectivities(self): {"contains_edge": False, "contains_node": False}, ) + log_regex = r"Ignoring request to remove.*" for kwargs in positive_kwargs: - with self.assertLogs(ugrid.logger, level="DEBUG") as log: + with self.assertLogs( + ugrid.logger, level="DEBUG", msg_regex=log_regex + ): self.mesh.remove_connectivities(**kwargs) - self.assertIn("Ignoring request to remove", log.output[0]) self.assertEqual(self.EDGE_NODE, self.mesh.edge_node_connectivity) for kwargs in negative_kwargs: with self.assertLogs(ugrid.logger, level="DEBUG") as log: # Check that the only debug log is the one we inserted. - ugrid.logger.debug("foo") + ugrid.logger.debug("foo", extra=dict(cls=None)) self.mesh.remove_connectivities(**kwargs) - self.assertEqual(1, len(log.output)) + self.assertEqual(1, len(log.records)) self.assertEqual(self.EDGE_NODE, self.mesh.edge_node_connectivity) def test_remove_coords(self): @@ -825,17 +827,19 @@ def test_remove_coords(self): {"attributes": {"test": 2}}, ) + log_regex = r"Ignoring request to remove.*" for kwargs in positive_kwargs: - with self.assertLogs(ugrid.logger, level="DEBUG") as log: + with self.assertLogs( + ugrid.logger, level="DEBUG", msg_regex=log_regex + ): self.mesh.remove_coords(**kwargs) - self.assertIn("Ignoring request to remove", log.output[0]) self.assertEqual(self.NODE_LON, self.mesh.node_coords.node_x) for kwargs in negative_kwargs: with self.assertLogs(ugrid.logger, level="DEBUG") as log: # Check that the only debug log is the one we inserted. - ugrid.logger.debug("foo") + ugrid.logger.debug("foo", extra=dict(cls=None)) self.mesh.remove_coords(**kwargs) - self.assertEqual(1, len(log.output)) + self.assertEqual(1, len(log.records)) self.assertEqual(self.NODE_LON, self.mesh.node_coords.node_x) # Test removal of optional connectivity. @@ -945,9 +949,9 @@ def test_add_connectivities_invalid(self): fake_cf_role = tests.mock.Mock( __class__=ugrid.Connectivity, cf_role="foo" ) - with self.assertLogs(ugrid.logger, level="DEBUG") as log: + log_regex = r"Not adding connectivity.*" + with self.assertLogs(ugrid.logger, level="DEBUG", msg_regex=log_regex): self.mesh.add_connectivities(fake_cf_role) - self.assertIn("Not adding connectivity", log.output[0]) def test_add_coords_face(self): # ADD coords. diff --git a/lib/iris/tests/unit/fileformats/netcdf/test_load_cubes.py b/lib/iris/tests/unit/fileformats/netcdf/test_load_cubes.py index 5ed908bfd0..8c51dbd130 100644 --- a/lib/iris/tests/unit/fileformats/netcdf/test_load_cubes.py +++ b/lib/iris/tests/unit/fileformats/netcdf/test_load_cubes.py @@ -314,6 +314,6 @@ def test_missing_mesh(self): _ = list(load_cubes(nc_path)) with PARSE_UGRID_ON_LOAD.context(): - with self.assertLogs(logger, level="DEBUG") as log: + log_regex = r"File does not contain mesh.*" + with self.assertLogs(logger, level="DEBUG", msg_regex=log_regex): _ = list(load_cubes(nc_path)) - self.assertIn("File does not contain mesh", log.output[0])