Merge pull request #946 from iiasa/ixmp4/quiet-init

Quiet logging from MESSAGE.initialize

Author: khaeru

RELEASE_NOTES.rst

@@ -1,8 +1,10 @@
-.. Next release
-.. ============
+Next release
+============
 
-.. All changes
-.. -----------
+All changes
+-----------
+
+- Filter log noise generated when loading scenarios created with :mod:`message_ix`/:mod:`ixmp` v3.10 and earlier (:pull:`946`).
 
 .. _v3.11.0:
 
@@ -32,7 +34,6 @@ Users **should**:
   and adjust |growth_new_capacity_up| or |initial_new_capacity_up| values as necessary.
   For the latter, :func:`.initial_new_capacity_up_v311` may be used.
 
-
 All changes
 -----------
 

message_ix/models.py

@@ -1,9 +1,11 @@
 import logging
+import re
 from collections import ChainMap
-from collections.abc import Mapping, MutableMapping
+from collections.abc import Iterator, Mapping, MutableMapping
+from contextlib import contextmanager
 from copy import copy
 from dataclasses import InitVar, dataclass, field
-from functools import partial
+from functools import cache, partial
 from pathlib import Path
 from typing import TYPE_CHECKING, Optional
 from warnings import warn
@@ -18,6 +20,8 @@
 from message_ix.util.scenario_data import REQUIRED_EQUATIONS, REQUIRED_VARIABLES
 
 if TYPE_CHECKING:
+    from logging import LogRecord
+
     import ixmp.core.scenario
 
     import message_ix.core
@@ -283,6 +287,48 @@ def _check_structure(scenario: "ixmp.core.scenario.Scenario"):
             yield name, info.ix_type, N, message
 
 
+@cache
+def _log_filter_pattern(cls: type[GAMSModel]) -> "re.Pattern":
+    """Return a compiled :class:`re.Pattern` for filtering log messages.
+
+    Messages like the following are matched:
+
+    - "Existing index sets of 'FOO' [] do not match …"
+    - "Existing index names of 'BAR' [] do not match …"
+
+    …where "FOO" or "BAR" are :any:`ItemType.EQU` or :any:`ItemType.VAR` among
+    the :attr:`cls.items <GAMSModel.items>`. Such log entries are generated by
+    :meth:`ixmp.
+
+    The result is :func:`functools.cache`'d, thus only generated once.
+    """
+    # Names of EQU or VAR-type items
+    names = sorted(k for k, v in cls.items.items() if v.type & ItemType.SOLUTION)
+
+    # Expression matching log message from ixmp.model.base.Model.initialize_items()
+    return re.compile(
+        rf"Existing index (set|name)s of '({'|'.join(names)})' \[\] do not match"
+    )
+
+
+@contextmanager
+def _filter_log_initialize_items(cls: type[GAMSModel]) -> Iterator[None]:
+    """Context manager to filter log messages related to existing items."""
+    pattern = _log_filter_pattern(cls)
+
+    def _filter(record: "LogRecord") -> bool:
+        # Retrieve the compiled expression
+        return not pattern.match(record.msg)
+
+    # Attach the filter to the ixmp.model logger
+    logger = logging.getLogger("ixmp.model.base")
+    logger.addFilter(_filter)
+    try:
+        yield
+    finally:
+        logger.removeFilter(_filter)
+
+
 class MESSAGE(GAMSModel):
     """Model class for MESSAGE."""
 
@@ -358,8 +404,11 @@ def initialize(cls, scenario: "ixmp.core.scenario.Scenario") -> None:
         if isinstance(scenario.platform._backend, JDBCBackend):
             items.pop("balance_equality")
 
-        # Initialize the ixmp items for MESSAGE
-        cls.initialize_items(scenario, items)
+        # Hide verbose log messages if `scenario` was created with message_ix <3.10 and
+        # is being loaded with v3.11 or later
+        with _filter_log_initialize_items(cls):
+            # Initialize the ixmp items for MESSAGE
+            cls.initialize_items(scenario, items)
 
         if not isinstance(scenario, Scenario):
             # Narrow type of `scenario`

message_ix/tests/test_models.py

@@ -1,33 +1,78 @@
+"""Tests of :class:`ixmp.model.base.Model` classes in :mod:`message_ix.models`."""
+
+import re
 from collections import defaultdict
+from typing import TYPE_CHECKING
 
 import ixmp
 import pytest
 from ixmp.backend.jdbc import JDBCBackend
 
 from message_ix.models import MESSAGE, MESSAGE_MACRO
 
+if TYPE_CHECKING:
+    from ixmp import Platform
+
+
+class TestMESSAGE:
+    def test_initialize(self, caplog, test_mp: "Platform") -> None:
+        # Expected numbers of items by type
+        exp = defaultdict(list)
+        for name, spec in MESSAGE.items.items():
+            exp[str(spec.type.name).lower()].append(name)
+
+        # balance_equality is removed in initialize() for JDBC
+        if isinstance(test_mp._backend, JDBCBackend):
+            exp["set"].remove("balance_equality")
+
+        # Use ixmp.Scenario to avoid invoking ixmp_source/Java code that automatically
+        # populates empty scenarios
+        s = ixmp.Scenario(test_mp, model="m", scenario="s", version="new")
+
+        # Initialization succeeds on a totally empty scenario
+        MESSAGE.initialize(s)
+
+        # The expected items exist
+        for ix_type, exp_names in exp.items():
+            obs_names = getattr(s, f"{ix_type}_list")()
+            assert sorted(obs_names) == sorted(exp_names)
+
+    def test_initialize_filter_log(self, caplog, test_mp: "Platform") -> None:
+        """Test :meth:`MESSAGE.initialize` logging under some conditions.
+
+        For :class:`.Scenario` created with message_ix v3.10 or earlier, equations and
+        variables may be initialized but have zero dimensions, thus empty lists of
+        "index sets" and "index names". When :class:`.Scenario` is instantiated,
+        :meth:`MESSAGE.initialize` is invoked, and in turn
+        :meth:`ixmp.model.base.Model.initialize_items`. This method generates many log
+        messages on level :data:`~logging.WARNING`.
 
-def test_initialize(test_mp: ixmp.Platform) -> None:
-    # Expected numbers of items by type
-    exp = defaultdict(list)
-    for name, spec in MESSAGE.items.items():
-        exp[str(spec.type.name).lower()].append(name)
+        In order to prevent this log noise, :func:`.models._filter_log_initialize_items`
+        is used. This test checks that it is effective.
+        """
+        # Use ixmp.Scenario to avoid invoking ixmp_source/Java code that automatically
+        # populates empty scenarios
+        s = ixmp.Scenario(test_mp, model="m", scenario="s", version="new")
 
-    # balance_equality is removed in initialize() for JDBC
-    if isinstance(test_mp._backend, JDBCBackend):
-        exp["set"].remove("balance_equality")
+        # Initialize an equation with no dimensions. This mocks the state of a Scenario
+        # created with message_ix v3.10 or earlier.
+        s.init_equ("NEW_CAPACITY_BOUND_LO", idx_sets=[], idx_names=[])
 
-    # Use ixmp.Scenario to avoid invoking ixmp_source/Java code that
-    # automatically populates empty scenarios
-    s = ixmp.Scenario(test_mp, "test_initialize", "test_initialize", version="new")
+        s.commit("")
+        s.set_as_default()
+        caplog.clear()
 
-    # Initialization succeeds on a totally empty scenario
-    MESSAGE.initialize(s)
+        # Initialize items.
+        MESSAGE.initialize(s)
 
-    # The expected items exist
-    for ix_type, exp_names in exp.items():
-        obs_names = getattr(s, f"{ix_type}_list")()
-        assert sorted(obs_names) == sorted(exp_names)
+        # Messages related to re-initializing items with 0 dimensions are filtered and
+        # do not reach `caplog`. This assertion fails with message_ix v3.10.
+        message_pattern = re.compile(
+            r"Existing index (name|set)s of 'NEW_CAPACITY_BOUND_LO' \[\] do not match "
+            r"\('node', '.*', 'year'\)"
+        )
+        extra = list(filter(message_pattern.match, caplog.messages))
+        assert not extra, f"{len(extra)} unwanted log messages: {extra}"
 
 
 def test_message_macro() -> None: