Logging fixes

lib/iris/experimental/ugrid/__init__.py

@@ -1229,7 +1229,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:
@@ -3332,7 +3332,11 @@ def identify(cls, variables, ignore=None, target=None, warn=True):
                                     f"{name}, referenced by netCDF variable "
                                     f"{nc_var_name}"
                                 )
-                                logger.debug(message)
+                                # TODO: reconsider logging level when we
+                                #  have consistent practice.
+                                logger.warning(
+                                    message, extra=dict(cls=cls.__name__)
+                                )
                         else:
                             # Restrict to non-string type i.e. not a
                             # CFLabelVariable.
@@ -3346,7 +3350,9 @@ def identify(cls, variables, ignore=None, target=None, warn=True):
                                     f"as a CF-UGRID connectivity - is a "
                                     f"CF-netCDF label variable."
                                 )
-                                logger.debug(message)
+                                logger.debug(
+                                    message, extra=dict(cls=cls.__name__)
+                                )
 
         return result
 
@@ -3403,7 +3409,11 @@ def identify(cls, variables, ignore=None, target=None, warn=True):
                                         f"referenced by netCDF variable "
                                         f"{nc_var_name}"
                                     )
-                                    logger.debug(message)
+                                    # TODO: reconsider logging level when we
+                                    #  have consistent practice.
+                                    logger.warning(
+                                        message, extra=dict(cls=cls.__name__)
+                                    )
                             else:
                                 # Restrict to non-string type i.e. not a
                                 # CFLabelVariable.
@@ -3420,7 +3430,9 @@ def identify(cls, variables, ignore=None, target=None, warn=True):
                                         f"coordinate - is a CF-netCDF label "
                                         f"variable."
                                     )
-                                    logger.debug(message)
+                                    logger.debug(
+                                        message, extra=dict(cls=cls.__name__)
+                                    )
 
         return result
 
@@ -3467,7 +3479,11 @@ def identify(cls, variables, ignore=None, target=None, warn=True):
                                 f"Missing CF-UGRID mesh variable {name}, "
                                 f"referenced by netCDF variable {nc_var_name}"
                             )
-                            logger.debug(message)
+                            # TODO: reconsider logging level when we have
+                            #  consistent practice.
+                            logger.warning(
+                                message, extra=dict(cls=cls.__name__)
+                            )
                     else:
                         # Restrict to non-string type i.e. not a
                         # CFLabelVariable.
@@ -3481,7 +3497,7 @@ def identify(cls, variables, ignore=None, target=None, warn=True):
                                 f"CF-UGRID mesh - is a CF-netCDF label "
                                 f"variable."
                             )
-                            logger.debug(message)
+                            logger.debug(message, extra=dict(cls=cls.__name__))
 
         return result
 
@@ -3673,7 +3689,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 +3702,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

lib/iris/tests/unit/experimental/ugrid/test_CFUGridAuxiliaryCoordinateVariable.py

@@ -214,19 +214,19 @@ def test_warn(self):
         }
 
         # Missing warning.
-        with self.assertLogs(logger, level="DEBUG") as log:
+        with self.assertLogs(logger) as log:
             result = CFUGridAuxiliaryCoordinateVariable.identify(
                 vars_all, warn=False
             )
-            self.assertEqual(0, len(log.output))
+            self.assertEqual(0, len(log.records))
             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],
-            )
+            rec = log.records[0]
+            self.assertEqual("WARNING", rec.levelname)
+            re_msg = rf"Missing CF-netCDF auxiliary coordinate variable {subject_name}.*"
+            self.assertRegex(rec.msg, re_msg)
             self.assertDictEqual({}, result)
 
         # String variable warning.
@@ -237,9 +237,13 @@ def test_warn(self):
             result = CFUGridAuxiliaryCoordinateVariable.identify(
                 vars_all, warn=False
             )
+            self.assertEqual(0, len(log.records))
             self.assertDictEqual({}, result)
 
             # Default is warn=True
             result = CFUGridAuxiliaryCoordinateVariable.identify(vars_all)
-            self.assertIn("is a CF-netCDF label variable", log.output[0])
+            rec = log.records[0]
+            self.assertEqual("DEBUG", rec.levelname)
+            re_msg = r".*is a CF-netCDF label variable.*"
+            self.assertRegex(rec.msg, re_msg)
             self.assertDictEqual({}, result)

lib/iris/tests/unit/experimental/ugrid/test_CFUGridConnectivityVariable.py

@@ -203,17 +203,19 @@ def test_warn(self):
         }
 
         # Missing warning.
-        with self.assertLogs(logger, level="DEBUG") as log:
+        with self.assertLogs(logger) as log:
             result = CFUGridConnectivityVariable.identify(vars_all, warn=False)
-            self.assertEqual(0, len(log.output))
+            self.assertEqual(0, len(log.records))
             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],
+            rec = log.records[0]
+            self.assertEqual("WARNING", rec.levelname)
+            re_msg = (
+                rf"Missing CF-UGRID connectivity variable {subject_name}.*"
             )
+            self.assertRegex(rec.msg, re_msg)
             self.assertDictEqual({}, result)
 
         # String variable warning.
@@ -222,9 +224,13 @@ def test_warn(self):
                 subject_name, "", np.bytes_
             )
             result = CFUGridConnectivityVariable.identify(vars_all, warn=False)
+            self.assertEqual(0, len(log.records))
             self.assertDictEqual({}, result)
 
             # Default is warn=True
             result = CFUGridConnectivityVariable.identify(vars_all)
-            self.assertIn("is a CF-netCDF label variable", log.output[0])
+            rec = log.records[0]
+            self.assertEqual("DEBUG", rec.levelname)
+            re_msg = r".*is a CF-netCDF label variable.*"
+            self.assertRegex(rec.msg, re_msg)
             self.assertDictEqual({}, result)

lib/iris/tests/unit/experimental/ugrid/test_CFUGridMeshVariable.py

@@ -196,16 +196,17 @@ def test_warn(self):
         }
 
         # Missing warning.
-        with self.assertLogs(logger, level="DEBUG") as log:
+        with self.assertLogs(logger) as log:
             result = CFUGridMeshVariable.identify(vars_all, warn=False)
-            self.assertEqual(0, len(log.output))
+            self.assertEqual(0, len(log.records))
             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]
-            )
+            rec = log.records[0]
+            self.assertEqual("WARNING", rec.levelname)
+            re_msg = rf"Missing CF-UGRID mesh variable {subject_name}.*"
+            self.assertRegex(rec.msg, re_msg)
             self.assertDictEqual({}, result)
 
         # String variable warning.
@@ -214,9 +215,13 @@ def test_warn(self):
                 subject_name, "", np.bytes_
             )
             result = CFUGridMeshVariable.identify(vars_all, warn=False)
+            self.assertEqual(0, len(log.records))
             self.assertDictEqual({}, result)
 
             # Default is warn=True
             result = CFUGridMeshVariable.identify(vars_all)
-            self.assertIn("is a CF-netCDF label variable", log.output[0])
+            rec = log.records[0]
+            self.assertEqual("DEBUG", rec.levelname)
+            re_msg = r".*is a CF-netCDF label variable.*"
+            self.assertRegex(rec.msg, re_msg)
             self.assertDictEqual({}, result)

lib/iris/tests/unit/experimental/ugrid/test_Mesh.py

@@ -194,7 +194,10 @@ def test_connectivities_locations(self):
 
         with self.assertLogs(ugrid.logger, level="DEBUG") as log:
             self.assertEqual([], func(contains_face=True))
-            self.assertIn("filter for non-existent", log.output[0])
+            rec = log.records[0]
+            self.assertEqual("DEBUG", rec.levelname)
+            re_msg = r".*filter for non-existent.*"
+            self.assertRegex(rec.msg, re_msg)
 
     def test_coord(self):
         # See Mesh.coords tests for thorough coverage of cases.
@@ -266,7 +269,10 @@ def test_coords_locations(self):
 
         with self.assertLogs(ugrid.logger, level="DEBUG") as log:
             self.assertEqual([], func(include_faces=True))
-            self.assertIn("filter non-existent", log.output[0])
+            rec = log.records[0]
+            self.assertEqual("DEBUG", rec.levelname)
+            re_msg = r".*filter non-existent.*"
+            self.assertRegex(rec.msg, re_msg)
 
     def test_edge_dimension(self):
         self.assertEqual(
@@ -620,7 +626,10 @@ def test_add_connectivities_invalid(self):
         face_node = self.FACE_NODE
         with self.assertLogs(ugrid.logger, level="DEBUG") as log:
             self.mesh.add_connectivities(face_node)
-            self.assertIn("Not adding connectivity", log.output[0])
+            rec = log.records[0]
+            self.assertEqual("DEBUG", rec.levelname)
+            re_msg = r"Not adding connectivity.*"
+            self.assertRegex(rec.msg, re_msg)
 
     def test_add_coords(self):
         # ADD coords.
@@ -727,7 +736,10 @@ def test_dimension_names(self):
 
         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])
+            rec = log.records[0]
+            self.assertEqual("DEBUG", rec.levelname)
+            re_msg = r"Not setting face_dimension.*"
+            self.assertRegex(rec.msg, re_msg)
         self.assertEqual(
             ugrid.Mesh1DNames("foo", "bar"), self.mesh.dimension_names()
         )
@@ -748,7 +760,10 @@ def test_edge_dimension_set(self):
     def test_face_dimension_set(self):
         with self.assertLogs(ugrid.logger, level="DEBUG") as log:
             self.mesh.face_dimension = "foo"
-            self.assertIn("Not setting face_dimension", log.output[0])
+            rec = log.records[0]
+            self.assertEqual("DEBUG", rec.levelname)
+            re_msg = r"Not setting face_dimension.*"
+            self.assertRegex(rec.msg, re_msg)
         self.assertIsNone(self.mesh.face_dimension)
 
     def test_node_dimension_set(self):
@@ -793,14 +808,17 @@ def test_remove_connectivities(self):
         for kwargs in positive_kwargs:
             with self.assertLogs(ugrid.logger, level="DEBUG") as log:
                 self.mesh.remove_connectivities(**kwargs)
-                self.assertIn("Ignoring request to remove", log.output[0])
+                rec = log.records[0]
+                self.assertEqual("DEBUG", rec.levelname)
+                re_msg = r"Ignoring request to remove.*"
+                self.assertRegex(rec.msg, re_msg)
             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")
                 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):
@@ -828,14 +846,17 @@ def test_remove_coords(self):
         for kwargs in positive_kwargs:
             with self.assertLogs(ugrid.logger, level="DEBUG") as log:
                 self.mesh.remove_coords(**kwargs)
-                self.assertIn("Ignoring request to remove", log.output[0])
+                rec = log.records[0]
+                self.assertEqual("DEBUG", rec.levelname)
+                re_msg = r"Ignoring request to remove.*"
+                self.assertRegex(rec.msg, re_msg)
             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")
                 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.
@@ -947,7 +968,10 @@ def test_add_connectivities_invalid(self):
         )
         with self.assertLogs(ugrid.logger, level="DEBUG") as log:
             self.mesh.add_connectivities(fake_cf_role)
-            self.assertIn("Not adding connectivity", log.output[0])
+            rec = log.records[0]
+            self.assertEqual("DEBUG", rec.levelname)
+            re_msg = r"Not adding connectivity.*"
+            self.assertRegex(rec.msg, re_msg)
 
     def test_add_coords_face(self):
         # ADD coords.

lib/iris/tests/unit/fileformats/netcdf/test_load_cubes.py

@@ -316,4 +316,7 @@ def test_missing_mesh(self):
         with PARSE_UGRID_ON_LOAD.context():
             with self.assertLogs(logger, level="DEBUG") as log:
                 _ = list(load_cubes(nc_path))
-                self.assertIn("File does not contain mesh", log.output[0])
+                rec = log.records[0]
+                self.assertEqual("DEBUG", rec.levelname)
+                re_msg = r"File does not contain mesh.*"
+                self.assertRegex(rec.msg, re_msg)