Merge pull request #399 from iiasa/feature/quiet

Add "quiet" option for GAMSModel

RELEASE_NOTES.rst

@@ -4,6 +4,8 @@ Next release
 All changes
 -----------
 
+- Deprecate :func:`.utils.logger` (:pull:`399`).
+- Add a `quiet` option to :meth:`.GAMSModel.solve` and use in testing (:pull:`399`).
 - :pull:`398`:
 
   - Fix :class:`.GAMSModel` would try to write GDX data to filenames containing invalid characters on Windows.

doc/api.rst

@@ -237,7 +237,7 @@ Utilities
 .. currentmodule:: ixmp.utils
 
 .. automodule:: ixmp.utils
-   :members: format_scenario_list, maybe_check_out, maybe_commit, parse_url, show_versions, update_par
+   :members: format_scenario_list, logger, maybe_check_out, maybe_commit, parse_url, show_versions, update_par
 
 
 Testing utilities

doc/reporting.rst

@@ -73,6 +73,7 @@ The following top-level objects from :mod:`genno` may also be imported from
       ~genno.core.computer.Computer.visualize
       ~genno.core.computer.Computer.write
 
+.. _reporting-config:
 
 Configuration
 =============

ixmp/__init__.py

@@ -45,8 +45,8 @@
 )
 
 
-# Configure the 'ixmp' logger: write messages to std out, defaulting to level
-# WARNING and above
+# Configure the 'ixmp' logger: write messages to stdout, defaulting to level WARNING
+# and above
 log = logging.getLogger(__name__)
 log.addHandler(logging.StreamHandler())
 log.setLevel(logging.WARNING)

ixmp/backend/jdbc.py

@@ -229,9 +229,8 @@ def __init__(self, jvmargs=None, **kwargs):
         # Invoke the parent constructor to initialize the cache
         super().__init__(cache_enabled=kwargs.pop("cache", True))
 
-        # Extract a log_level keyword argument before _create_properties().
-        # By default, use the same level as the 'ixmp' logger, whatever that
-        # has been set to.
+        # Extract a log_level keyword argument before _create_properties(). By default,
+        # use the same level as the 'ixmp' logger, whatever that has been set to.
         ixmp_logger = logging.getLogger("ixmp")
         log_level = kwargs.pop("log_level", ixmp_logger.getEffectiveLevel())
 
@@ -300,8 +299,8 @@ def gc(cls):
     # Platform methods
 
     def set_log_level(self, level):
-        # Set the level of the 'ixmp.backend.jdbc' logger. Messages are handled
-        # by the 'ixmp' logger; see ixmp/__init__.py.
+        # Set the level of the 'ixmp.backend.jdbc' logger. Messages are handled by the
+        # 'ixmp' logger; see ixmp/__init__.py.
         log.setLevel(level)
 
         # Translate to Java log level and set

ixmp/core.py

@@ -12,7 +12,7 @@
 from ._config import config
 from .backend import BACKENDS, FIELDS, ItemType
 from .model import get_model
-from .utils import as_str_list, check_year, logger, parse_url, year_list
+from .utils import as_str_list, check_year, parse_url, year_list
 
 log = logging.getLogger(__name__)
 
@@ -120,14 +120,14 @@ def set_log_level(self, level):
             )
 
         # Set the level for the 'ixmp' logger
-        # NB this may produce unexpected results when multiple Platforms exist
-        #    and different log levels are set. To fix, could use a sub-logger
-        #    per Platform instance.
+        # NB this may produce unexpected results when multiple Platforms exist and
+        #    different log levels are set. To fix, could use a sub-logger per Platform
+        #    instance.
         logging.getLogger("ixmp").setLevel(level)
 
-        # Set the level for the 'ixmp.backend.*' logger. For JDBCBackend, this
-        # also has the effect of setting the level for Java log messages that
-        # are printed to stdout.
+        # Set the level for the 'ixmp.backend.*' logger. For JDBCBackend, this also has
+        # the effect of setting the level for Java log messages that are printed to
+        # stdout.
         self._backend.set_log_level(level)
 
     def get_log_level(self):
@@ -262,8 +262,7 @@ def add_unit(self, unit, comment="None"):
             database user and timestamp are appended automatically.
         """
         if unit in self.units():
-            msg = "unit `{}` is already defined in the platform instance"
-            logger().info(msg.format(unit))
+            log.info(f"unit `{unit}` is already defined in the platform instance")
             return
 
         self._backend.set_unit(unit, comment)
@@ -344,24 +343,23 @@ def add_region_synonym(self, region, mapped_to):
     def timeslices(self):
         """Return all subannual timeslices defined in this Platform instance.
 
-        Timeslices are a way to represent subannual temporal resolution in
-        timeseries data. A timeslice consists of a **name** (e.g., 'january',
-        'summer'), a **category** (e.g., 'months', 'seasons'), and a
-        **duration** given relative to a full year.
+        Timeslices are a way to represent subannual temporal resolution in timeseries
+        data. A timeslice consists of a **name** (e.g., 'january', 'summer'), a
+        **category** (e.g., 'months', 'seasons'), and a **duration** given relative to a
+        full year.
 
-        The category and duration do not have any functional relevance within
-        the ixmp framework, but they may be useful for pre- or post-processing.
-        For example, they can be used to filter all timeslices of a certain
-        category (e.g., all months) from the :class:`pandas.DataFrame` returned
-        by this function or to aggregate subannual data to full-year results.
+        The category and duration do not have any functional relevance within the ixmp
+        framework, but they may be useful for pre- or post-processing.  For example,
+        they can be used to filter all timeslices of a certain category (e.g., all
+        months) from the :class:`pandas.DataFrame` returned by this function or to
+        aggregate subannual data to full-year results.
 
-        A timeslice is related to the index set 'time'
-        in a :class:`message_ix.Scenario` to indicate a subannual temporal
-        dimension. Alas, timeslices and set elements of time have to be
-        initialized/defined independently.
+        A timeslice is related to the index set 'time' in a :class:`message_ix.Scenario`
+        to indicate a subannual temporal dimension. Alas, timeslices and set elements of
+        time have to be initialized/defined independently.
 
-        See :meth:`add_timeslice` to initialize additional timeslices in the
-        Platform instance.
+        See :meth:`add_timeslice` to initialize additional timeslices in the Platform
+        instance.
 
         Returns
         -------
@@ -392,7 +390,7 @@ def add_timeslice(self, name, category, duration):
             existing_duration = slices.loc[name].duration
             if not np.isclose(duration, existing_duration):
                 raise ValueError(msg.format(name, existing_duration))
-            logger().info(msg.format(name, duration))
+            log.info(msg.format(name, duration))
         else:
             self._backend.set_timeslice(name, category, duration)
 
@@ -502,7 +500,7 @@ def __del__(self):
         # Instruct the back end to free memory associated with the TimeSeries
         try:
             self._backend("del_ts")
-        except ReferenceError:
+        except (AttributeError, ReferenceError):
             pass  # The Platform has already been garbage-collected
 
     # Transactions and versioning
@@ -613,14 +611,14 @@ def add_timeseries(self, df, meta=False, year_lim=(None, None)):
             ).reset_index()
         df.set_index(["region", "variable", "unit", "subannual"], inplace=True)
 
-        # Discard non-numeric columns, e.g. 'model', 'scenario',
-        # write warning about non-expected cols to log
+        # Discard non-numeric columns, e.g. 'model', 'scenario', write warning about
+        # non-expected cols to log
         year_cols = year_list(df.columns)
         other_cols = [
             i for i in df.columns if i not in ["model", "scenario"] + year_cols
         ]
         if len(other_cols) > 0:
-            logger().warning(f"dropping index columns {other_cols} from data")
+            log.warning(f"Dropped extra column(s) {other_cols} from data")
 
         df = df.loc[:, year_cols]
 
@@ -975,7 +973,7 @@ def load_scenario_data(self):
             raise ValueError("Cache must be enabled to load scenario data")
 
         for ix_type in "equ", "par", "set", "var":
-            logger().info("Caching {} data".format(ix_type))
+            log.debug(f"Cache {repr(ix_type)} data")
             get_func = getattr(self, ix_type)
             for name in getattr(self, "{}_list".format(ix_type))():
                 get_func(name)
@@ -1555,9 +1553,7 @@ def clone(
         """
         if shift_first_model_year is not None:
             if keep_solution:
-                logger().warning(
-                    "Overriding keep_solution=True for " "shift_first_model_year"
-                )
+                log.warning("Override keep_solution=True for shift_first_model_year")
                 keep_solution = False
 
         platform = platform or self.platform

ixmp/model/gams.py

@@ -137,7 +137,12 @@ class GAMSModel(Model):
         control solver options or behaviour. See the `GAMS Documentation <https://www.gams.com/latest/docs/UG_GamsCall.html#UG_GamsCall_ListOfCommandLineParameters>`_.
         For example:
 
-        - ``'LogOption=4'`` prints output to stdout (not console) and the log file.
+        - ``["iterLim=10"]`` limits the solver to 10 iterations.
+    quiet: bool, optional
+        If :obj:`True`, add "LogOption=2" to `gams_args` to redirect most console
+        output during the model run to the log file. Default :obj:`False`, so
+        "LogOption=4" is added. Any "LogOption" value provided explicitly via
+        `gams_args` takes precedence.
     check_solution : bool, optional
         If :obj:`True`, raise an exception if the GAMS solver did not reach optimality.
         (Only for MESSAGE-scheme Scenarios.)
@@ -153,19 +158,20 @@ class GAMSModel(Model):
     #: Model name.
     name = "default"
 
-    #: Default model options:
+    #: Default values and format strings for options.
     defaults: Mapping[str, object] = {
         "model_file": "{model_name}.gms",
         "case": "{scenario.model}_{scenario.scenario}",
         "in_file": str(Path("{cwd}", "{model_name}_in.gdx")),
         "out_file": str(Path("{cwd}", "{model_name}_out.gdx")),
         "solve_args": ['--in="{in_file}"', '--out="{out_file}"'],
         # Not formatted
-        "gams_args": ["LogOption=4"],
+        "gams_args": [],
         "check_solution": True,
         "comment": None,
         "equ_list": None,
         "var_list": None,
+        "quiet": False,
         "use_temp_dir": True,
     }
 
@@ -176,6 +182,11 @@ def __init__(self, name_=None, **model_options):
         for arg_name, default in self.defaults.items():
             setattr(self, arg_name, model_options.get(arg_name, default))
 
+        # Check whether a subclass or user already set LogOption in `gams_args`
+        if not any("LogOption" in arg for arg in self.gams_args):
+            # Not set; use `quiet` to determine the value
+            self.gams_args.append(f"LogOption={'4' if self.quiet else '2'}")
+
     def format_exception(self, exc, model_file):
         """Format a user-friendly exception when GAMS errors."""
         msg = [

ixmp/reporting/reporter.py

@@ -100,6 +100,6 @@ def finalize(self, scenario: Scenario) -> None:
     def set_filters(self, **filters) -> None:
         """Apply `filters` ex ante (before computations occur).
 
-        See the description of :func:`.filters` under :ref:`config-ixmp`.
+        See the description of :func:`.filters` under :ref:`reporting-config`.
         """
         self.configure(filters=filters)

ixmp/testing.py

@@ -317,17 +317,21 @@ def populate_test_platform(platform):
     s4.set_as_default()
 
 
-def make_dantzig(mp: Platform, solve=False) -> Scenario:
+def make_dantzig(mp: Platform, solve: bool = False, quiet: bool = False) -> Scenario:
     """Return :class:`ixmp.Scenario` of Dantzig's canning/transport problem.
 
     Parameters
     ----------
-    mp : ixmp.Platform
+    mp : .Platform
         Platform on which to create the scenario.
-    solve : bool or os.PathLike
-        If not :obj:`False`, then *solve* is interpreted as a path to a
-        directory, and the model ``transport_ixmp.gms`` in the directory is run
-        for the scenario.
+    solve : bool, optional
+        If :obj:`True`. then solve the scenario before returning. Default :obj:`False`.
+    quiet : bool, optional
+        If :obj:`True`, suppress console output when solving.
+
+    Returns
+    -------
+    .Scenario
 
     See also
     --------
@@ -361,7 +365,7 @@ def make_dantzig(mp: Platform, solve=False) -> Scenario:
 
     if solve:
         # Solve the model using the GAMS code provided in the `tests` folder
-        scen.solve(model="dantzig", case="transport_standard")
+        scen.solve(model="dantzig", case="transport_standard", quiet=quiet)
 
     # add timeseries data for testing `clone(keep_solution=False)`
     # and `remove_solution()`
@@ -419,13 +423,12 @@ def run_notebook(nb_path, tmp_path, env=None, kernel=None, allow_errors=False):
         asyncio.set_event_loop_policy(asyncio.WindowsSelectorEventLoopPolicy())
 
     # Read the notebook
-    with open(nb_path, encoding="utf-8") as f:
-        nb = nbformat.read(f, as_version=4)
+    nb = nbformat.read(nb_path, as_version=4)
 
     # Create a client and use it to execute the notebook
     client = NotebookClient(
         nb,
-        timeout=60,
+        timeout=10,
         kernel_name=kernel or f"python{sys.version_info[0]}",
         allow_errors=allow_errors,
         resources=dict(metadata=dict(path=tmp_path)),
@@ -492,9 +495,8 @@ def get_cell_output(nb, name_or_index, kind="data"):
 def assert_logs(caplog, message_or_messages=None, at_level=None):
     """Assert that *message_or_messages* appear in logs.
 
-    Use assert_logs as a context manager for a statement that is expected to
-    trigger certain log messages. assert_logs checks that these messages are
-    generated.
+    Use assert_logs as a context manager for a statement that is expected to trigger
+    certain log messages. assert_logs checks that these messages are generated.
 
     Example
     -------
@@ -510,8 +512,7 @@ def test_foo(caplog):
     message_or_messages : str or list of str
         String(s) that must appear in log messages.
     at_level : int, optional
-        Messages must appear on 'ixmp' or a sub-logger with at least this
-        level.
+        Messages must appear on 'ixmp' or a sub-logger with at least this level.
     """
     # Wrap a string in a list
     expected = (

ixmp/tests/core/test_platform.py

@@ -1,4 +1,6 @@
 """Test functionality of ixmp.Platform."""
+import logging
+import re
 from sys import getrefcount
 from weakref import getweakrefcount
 
@@ -8,11 +10,12 @@
 from pytest import raises
 
 import ixmp
+from ixmp.testing import assert_logs
 
 
 def test_init():
     with pytest.raises(
-        ValueError, match="backend class 'foo' not among " r"\['jdbc'\]"
+        ValueError, match=re.escape("backend class 'foo' not among ['jdbc']")
     ):
         ixmp.Platform(backend="foo")
 
@@ -304,14 +307,18 @@ def test_add_timeslice(test_mp):
     assert all([list(obs.iloc[0]) == ["January, 1st", "Days", 1.0 / 366]])
 
 
-def test_add_timeslice_duplicate_raise(test_mp):
+def test_add_timeslice_duplicate(caplog, test_mp):
     test_mp.add_timeslice("foo_slice", "foo_category", 0.2)
-    # adding same name with different duration raises an error
-    with raises(
-        ValueError, match="timeslice `foo_slice` already defined with " "duration 0.2"
-    ):
+
+    # Adding same name with different duration raises an error
+    msg = "timeslice `foo_slice` already defined with duration 0.2"
+    with raises(ValueError, match=re.escape(msg)):
         test_mp.add_timeslice("foo_slice", "bar_category", 0.3)
 
+    # Re-adding with the same duration only logs a message
+    with assert_logs(caplog, msg, at_level=logging.INFO):
+        test_mp.add_timeslice("foo_slice", "bar_category", 0.2)
+
 
 def test_weakref():
     """Weak references allow Platforms to be del'd while Scenarios live."""
@@ -336,16 +343,16 @@ def test_weakref():
     # Make a local reference to the backend
     backend = mp._backend
 
-    # Delete the Platform. Note that this only has an effect if there are no
-    # existing references to it
+    # Delete the Platform. Note that this only has an effect if there are no existing
+    # references to it
     del mp
 
     # s.platform is a dead weak reference, so it can't be accessed
     with pytest.raises(ReferenceError):
         s.platform._backend
 
-    # There is only one remaining reference to the backend: the *backend* name
-    # in the local scope
+    # There is only one remaining reference to the backend: the *backend* name in the
+    # local scope
     assert getrefcount(backend) - 1 == 1
 
     # The backend is garbage-collected at this point