Lint rule to check for incorrect logging in Python modules (project-chip#41112)

* Lint rule to check for incorrect logging in Python modules

* Fix logging in Python controller

* Fix logging in testing infrastructure

* Fix logging in scripts modules

* Migrate away from deprecated 'logging.warn' method

* Restyled by isort

* Fix lint issues

* Change case according to copilot suggestion

---------

Co-authored-by: Restyled.io <[email protected]>

Author: arkq

.github/workflows/lint.yml

@@ -426,3 +426,18 @@ jobs:
                   # Ignore uses of `System::Clock::Literals`, because that's the only way to have things using _ms32 or whatnot
                   # in a header file.
                   git grep -I -n -e '^using namespace' --and --not -e 'System::Clock::Literals' -- './**/*.h' ':(exclude)src/platform/*/BLEManager*.h' ':(exclude)./examples' ':(exclude)./third_party' && exit 1 || exit 0
+
+            # git grep exits with 0 if it finds a match, but we want
+            # to fail (exit nonzero) on match.
+            - name:
+                  Check for a direct use of the "logging" module for logging.
+                  Instead one should use a local logger with a name based on
+                  the module name.
+              if: always()
+              run: |
+                  git grep -I -n -E -e 'logging[.](log|debug|info|warn|warning|error|critical|exception)[(]' -- \
+                    'scripts/py_matter_idl' \
+                    'scripts/py_matter_yamltests' \
+                    'src/controller/python' \
+                    'src/python_testing/matter_testing_infrastructure' \
+                    && exit 1 || exit 0

scripts/build/build/__init__.py

@@ -76,7 +76,7 @@ def Build(self):
 
     def CleanOutputDirectories(self):
         for builder in self.builders:
-            logging.warn('Cleaning %s', builder.output_dir)
+            logging.warning('Cleaning %s', builder.output_dir)
             if os.path.exists(builder.output_dir):
                 shutil.rmtree(builder.output_dir)
 

scripts/py_matter_idl/matter/idl/backwards_compatibility.py

@@ -24,6 +24,8 @@
 from matter.idl.matter_idl_parser import CreateParser
 from matter.idl.matter_idl_types import ApiMaturity, Attribute, Bitmap, Cluster, Command, Enum, Event, Field, Idl, Struct
 
+LOGGER = logging.getLogger(__name__)
+
 
 class Compatibility(enum.Enum):
     UNKNOWN = enum.auto()
@@ -70,10 +72,9 @@ def __init__(self, original: Idl, updated: Idl):
         self._updated_idl = updated
         self.compatible = Compatibility.UNKNOWN
         self.errors: List[str] = []
-        self.logger = logging.getLogger(__name__)
 
     def _mark_incompatible(self, reason: str):
-        self.logger.error(reason)
+        LOGGER.error(reason)
         self.errors.append(reason)
         self.compatible = Compatibility.INCOMPATIBLE
 
@@ -157,7 +158,7 @@ def _check_event_compatible(self, cluster_name: str, event: Event, updated_event
             f"Event {cluster_name}::{event.name}", event.fields, updated_event.fields)
 
     def _check_command_compatible(self, cluster_name: str, command: Command, updated_command: Optional[Command]):
-        self.logger.debug(f"  Checking command {cluster_name}::{command.name}")
+        LOGGER.debug(f"  Checking command {cluster_name}::{command.name}")
         if not updated_command:
             self._mark_incompatible(
                 f"Command {cluster_name}::{command.name} was removed")
@@ -180,7 +181,7 @@ def _check_command_compatible(self, cluster_name: str, command: Command, updated
                 f"Command {cluster_name}::{command.name} qualities changed from {command.qualities} to {updated_command.qualities}")
 
     def _check_struct_compatible(self, cluster_name: str, original: Struct, updated: Optional[Struct]):
-        self.logger.debug(f"  Checking struct {original.name}")
+        LOGGER.debug(f"  Checking struct {original.name}")
         if not updated:
             self._mark_incompatible(
                 f"Struct {cluster_name}::{original.name} has been deleted.")
@@ -202,7 +203,7 @@ def _check_struct_compatible(self, cluster_name: str, original: Struct, updated:
                 f"Struct {cluster_name}::{original.name} has modified qualities")
 
     def _check_attribute_compatible(self, cluster_name: str, original: Attribute, updated: Optional[Attribute]):
-        self.logger.debug(
+        LOGGER.debug(
             f"  Checking attribute {cluster_name}::{original.definition.name}")
         if not updated:
             self._mark_incompatible(
@@ -293,7 +294,7 @@ def _check_cluster_list_compatible(self, original: List[Cluster], updated: List[
             self._check_cluster_compatible(original_cluster, updated_cluster)
 
     def _check_cluster_compatible(self, original_cluster: Cluster, updated_cluster: Optional[Cluster]):
-        self.logger.debug(
+        LOGGER.debug(
             f"Checking cluster {original_cluster.name}")
         if not updated_cluster:
             self._mark_incompatible(
@@ -377,10 +378,10 @@ def main(log_level, old_idl, new_idl):
         fmt='%(asctime)s %(levelname)-7s %(message)s',
     )
 
-    logging.info("Parsing OLD idl from %s" % old_idl)
+    LOGGER.info("Parsing OLD idl from %s" % old_idl)
     old_tree = CreateParser().parse(open(old_idl, "rt").read())
 
-    logging.info("Parsing NEW idl from %s" % new_idl)
+    LOGGER.info("Parsing NEW idl from %s" % new_idl)
     new_tree = CreateParser().parse(open(new_idl, "rt").read())
 
     if not is_backwards_compatible(original=old_tree, updated=new_tree):

scripts/py_matter_idl/matter/idl/data_model_xml/__init__.py

@@ -27,6 +27,8 @@
 from matter.idl.matter_idl_parser import CreateParser
 from matter.idl.matter_idl_types import Idl
 
+LOGGER = logging.getLogger(__name__)
+
 
 class ParseHandler(xml.sax.handler.ContentHandler):
     """A parser for data model XML data definitions.
@@ -73,13 +75,13 @@ def endDocument(self):
             raise Exception("Unexpected nesting!")
 
     def startElement(self, name: str, attrs):
-        logging.debug("ELEMENT START: %r / %r" % (name, attrs))
+        LOGGER.debug("ELEMENT START: %r / %r" % (name, attrs))
         self._context.path.push(name)
         self._processing_stack.append(
             self._processing_stack[-1].GetNextProcessor(name, attrs))
 
     def endElement(self, name: str):
-        logging.debug("ELEMENT END: %r" % name)
+        LOGGER.debug("ELEMENT END: %r" % name)
 
         last = self._processing_stack.pop()
         last.EndProcessing()
@@ -119,16 +121,16 @@ def ParseXmls(sources: List[ParseSource], include_meta_data=True) -> Idl:
     handler = ParseHandler(include_meta_data=include_meta_data)
 
     for source in sources:
-        logging.info('Parsing %s...' % source.source_file_name)
+        LOGGER.info('Parsing %s...' % source.source_file_name)
         handler.PrepareParsing(source.source_file_name)
 
         parser = xml.sax.make_parser()
         parser.setContentHandler(handler)
         try:
             parser.parse(source.source)
         except AssertionError as e:
-            logging.error("AssertionError %s at %r", e,
-                          handler._context.GetCurrentLocationMeta())
+            LOGGER.error("AssertionError %s at %r", e,
+                         handler._context.GetCurrentLocationMeta())
             raise
 
     return handler.Finish()
@@ -223,15 +225,15 @@ def main(log_level, no_print, output, compare, compare_output, filenames):
     )
 
     if (compare is None) != (compare_output is None):
-        logging.error(
+        LOGGER.error(
             "Either both or none of --compare AND --compare-output must be set")
         sys.exit(1)
 
-    logging.info("Starting to parse ...")
+    LOGGER.info("Starting to parse ...")
 
     sources = [ParseSource(source=name) for name in filenames]
     data = ParseXmls(sources)
-    logging.info("Parse completed")
+    LOGGER.info("Parse completed")
 
     if compare:
         other_idl = CreateParser(skip_meta=True).parse(

scripts/py_matter_idl/matter/idl/data_model_xml/handlers/__init__.py

@@ -22,7 +22,7 @@
 from .handlers import ClusterHandler
 from .parsing import NormalizeName
 
-LOGGER = logging.getLogger('data-model-xml-data-parsing')
+LOGGER = logging.getLogger(__name__)
 
 
 def contains_valid_cluster_id(attrs: AttributesImpl) -> bool:

scripts/py_matter_idl/matter/idl/data_model_xml/handlers/context.py

@@ -18,6 +18,8 @@
 
 from matter.idl.matter_idl_types import Cluster, Idl, ParseMetaData
 
+LOGGER = logging.getLogger(__name__)
+
 
 class IdlPostProcessor:
     """Defines a callback that will apply after an entire parsing
@@ -119,7 +121,7 @@ def MarkTagNotHandled(self):
             if where:
                 msg = msg + " at " + where
 
-            logging.warning(msg)
+            LOGGER.warning(msg)
             self._not_handled.add(path)
 
     def AddIdlPostProcessor(self, processor: IdlPostProcessor, has_priority: bool = False):

scripts/py_matter_idl/matter/idl/data_model_xml/handlers/derivation.py

@@ -13,6 +13,7 @@
 #    See the License for the specific language governing permissions and
 #    limitations under the License.
 #
+
 import dataclasses
 import logging
 from typing import Iterable, Optional, Protocol, TypeVar
@@ -22,7 +23,7 @@
 from .context import Context, IdlPostProcessor
 from .parsing import NormalizeName
 
-LOGGER = logging.getLogger('data-model-xml-data-parsing')
+LOGGER = logging.getLogger(__name__)
 
 T = TypeVar("T")
 

scripts/py_matter_idl/matter/idl/data_model_xml/handlers/handlers.py

@@ -26,7 +26,7 @@
 from .parsing import (ApplyConstraint, AttributesToAttribute, AttributesToBitFieldConstantEntry, AttributesToCommand,
                       AttributesToEvent, AttributesToField, NormalizeDataType, NormalizeName, ParseInt, StringToAccessPrivilege)
 
-LOGGER = logging.getLogger('data-model-xml-parser')
+LOGGER = logging.getLogger(__name__)
 
 
 def is_unused_name(attrs: AttributesImpl):
@@ -267,8 +267,8 @@ def GetNextProcessor(self, name: str, attrs: AttributesImpl):
         elif name == "item":
             for key in ["name", "value"]:
                 if key not in attrs:
-                    logging.error("Enumeration %s entry is missing a '%s' entry (at %r)",
-                                  self._enum.name, key, self.context.GetCurrentLocationMeta())
+                    LOGGER.error("Enumeration %s entry is missing a '%s' entry (at %r)",
+                                 self._enum.name, key, self.context.GetCurrentLocationMeta())
                     # bad entry, nothing I can do about it.
                     return BaseHandler(self.context, handled=HandledDepth.ENTIRE_TREE)
 

scripts/py_matter_idl/matter/idl/data_model_xml/handlers/parsing.py

@@ -21,7 +21,7 @@
 from matter.idl.generators.type_definitions import GetDataTypeSizeInBits, IsSignedDataType
 from matter.idl.matter_idl_types import AccessPrivilege, Attribute, Command, ConstantEntry, DataType, Event, EventPriority, Field
 
-LOGGER = logging.getLogger('data-model-xml-data-parsing')
+LOGGER = logging.getLogger(__name__)
 
 
 @dataclass
@@ -170,7 +170,7 @@ def NormalizeName(name: str) -> str:
 
     while '_' in name:
         idx = name.find('_')
-        name = name[:idx] + name[idx+1].upper() + name[idx+2:]
+        name = name[:idx] + name[idx + 1].upper() + name[idx + 2:]
 
     return name
 
@@ -271,8 +271,8 @@ def AttributesToEvent(attrs: AttributesImpl) -> Event:
     elif attrs["priority"] == "debug":
         priority = EventPriority.DEBUG
     elif attrs["priority"] == "desc":
-        LOGGER.warn("Found an event with 'desc' priority: %s" %
-                    [item for item in attrs.items()])
+        LOGGER.warning("Found an event with 'desc' priority: %s" %
+                       [item for item in attrs.items()])
         priority = EventPriority.CRITICAL
     else:
         raise Exception("UNKNOWN event priority: %r" % attrs["priority"])
@@ -302,7 +302,7 @@ def AttributesToCommand(attrs: AttributesImpl) -> Command:
     assert "name" in attrs
 
     if "response" not in attrs:
-        LOGGER.warn(f"Command {attrs['name']} has no response set.")
+        LOGGER.warning(f"Command {attrs['name']} has no response set.")
         # Matter IDL has no concept of "no response sent"
         # Example is DoorLock::"Operating Event Notification"
         #
@@ -362,4 +362,4 @@ def ApplyConstraint(attrs, field: Field):
         field.data_type.min_length = ParseOptionalInt(attrs["from"])
         field.data_type.max_length = ParseOptionalInt(attrs["to"])
     else:
-        logging.error(f"UNKNOWN constraint type {constraint_type}")
+        LOGGER.error(f"UNKNOWN constraint type {constraint_type}")

scripts/py_matter_idl/matter/idl/generators/__init__.py

@@ -23,6 +23,8 @@
 from .filters import RegisterCommonFilters
 from .storage import GeneratorStorage
 
+LOGGER = logging.getLogger(__name__)
+
 
 class CodeGenerator:
     """
@@ -99,11 +101,11 @@ def internal_render_one_output(self, template_path: str, output_file_name: str,
           output_file_name - File name that the template is to be generated to.
           vars             - variables used for template generation
         """
-        logging.info("File to be generated: %s" % output_file_name)
+        LOGGER.info("File to be generated: %s" % output_file_name)
         if self.dry_run:
             return
 
-        logging.info(f"Template path: {template_path}, CWD: {os.getcwd()}")
+        LOGGER.info(f"Template path: {template_path}, CWD: {os.getcwd()}")
         rendered = self.jinja_env.get_template(template_path).render(vars)
 
         # Report regardless if it has changed or not. This is because even if
@@ -112,6 +114,6 @@ def internal_render_one_output(self, template_path: str, output_file_name: str,
         self.storage.report_output_file(output_file_name)
 
         if rendered == self.storage.get_existing_data(output_file_name):
-            logging.info("File content not changed")
+            LOGGER.info("File content not changed")
         else:
             self.storage.write_new_data(output_file_name, rendered)