diff --git a/RELEASE_NOTES.rst b/RELEASE_NOTES.rst index 59419ff62..8844af505 100644 --- a/RELEASE_NOTES.rst +++ b/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. diff --git a/doc/api.rst b/doc/api.rst index eb2b6edc1..5dc8d787e 100644 --- a/doc/api.rst +++ b/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 diff --git a/doc/reporting.rst b/doc/reporting.rst index c83fd4a01..c9f325fcf 100644 --- a/doc/reporting.rst +++ b/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 ============= diff --git a/ixmp/__init__.py b/ixmp/__init__.py index c9118e096..d9975c343 100644 --- a/ixmp/__init__.py +++ b/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) diff --git a/ixmp/backend/jdbc.py b/ixmp/backend/jdbc.py index b66398ed9..44cdabf72 100644 --- a/ixmp/backend/jdbc.py +++ b/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 diff --git a/ixmp/core.py b/ixmp/core.py index 4c39a5f86..a9b331df8 100644 --- a/ixmp/core.py +++ b/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 diff --git a/ixmp/model/gams.py b/ixmp/model/gams.py index 10a4751b7..ea54a0eb7 100644 --- a/ixmp/model/gams.py +++ b/ixmp/model/gams.py @@ -137,7 +137,12 @@ class GAMSModel(Model): control solver options or behaviour. See the `GAMS Documentation `_. 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,7 +158,7 @@ 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}", @@ -161,11 +166,12 @@ class GAMSModel(Model): "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 = [ diff --git a/ixmp/reporting/reporter.py b/ixmp/reporting/reporter.py index 96b45247f..76c5bf59c 100644 --- a/ixmp/reporting/reporter.py +++ b/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) diff --git a/ixmp/testing.py b/ixmp/testing.py index accdc69f3..fd6c9e7d6 100644 --- a/ixmp/testing.py +++ b/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 = ( diff --git a/ixmp/tests/core/test_platform.py b/ixmp/tests/core/test_platform.py index 3517cc31e..1838e3886 100644 --- a/ixmp/tests/core/test_platform.py +++ b/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 diff --git a/ixmp/tests/core/test_timeseries.py b/ixmp/tests/core/test_timeseries.py index a2f8eef25..c9c5bb8c6 100644 --- a/ixmp/tests/core/test_timeseries.py +++ b/ixmp/tests/core/test_timeseries.py @@ -10,8 +10,8 @@ from ixmp.core import IAMC_IDX # Test data. -# NB the columns are in a specific order; model and scenario come last in the -# data returned by ixmp. +# NB the columns are in a specific order; model and scenario come last in the data +# returned by ixmp. # TODO fix this; model and scenario should come first, matching the IAMC order. DATA = { 0: pd.DataFrame.from_dict( @@ -56,8 +56,8 @@ scenario="scenario name", ) ), - # NB the columns for geodata methods are inconsistent with those for time- - # series data + # NB the columns for geodata methods are inconsistent with those for time-series + # data "geo": pd.DataFrame.from_dict( dict( region="World", @@ -132,10 +132,9 @@ def transact(ts, condition=True, commit_message=""): # Tests of ixmp.TimeSeries. # -# Since Scenario is a subclass of TimeSeries, all TimeSeries functionality -# should work exactly the same way on Scenario instances. The *ts* fixture is -# parametrized to yield both TimeSeries and Scenario objects, so every test -# is run on each type. +# Since Scenario is a subclass of TimeSeries, all TimeSeries functionality should work +# exactly the same way on Scenario instances. The *ts* fixture is parametrized to yield +# both TimeSeries and Scenario objects, so every test is run on each type. @pytest.fixture(scope="function", params=[TimeSeries, Scenario]) @@ -246,9 +245,7 @@ def test_add_timeseries_with_extra_col(caplog, ts, fmt): ts.add_timeseries(data) # TODO: add check that warning message is displayed ts.commit("") - assert ["dropping index columns ['climate_model'] from data"] == [ - rec.message for rec in caplog.records - ] + assert ["Dropped extra column(s) ['climate_model'] from data"] == caplog.messages @pytest.mark.parametrize("fmt", ["long", "wide"]) diff --git a/ixmp/tests/test_integration.py b/ixmp/tests/test_integration.py index c38838579..359092576 100644 --- a/ixmp/tests/test_integration.py +++ b/ixmp/tests/test_integration.py @@ -12,7 +12,7 @@ TS_DF_CLEARED.loc[0, 2005] = np.nan -def test_run_clone(test_mp, caplog): +def test_run_clone(caplog, test_mp): caplog.set_level(logging.WARNING) # this test is designed to cover the full functionality of the GAMS API @@ -37,7 +37,7 @@ def test_run_clone(test_mp, caplog): # cloning with `keep_solution=True` and `first_model_year` raises a warning scen.clone(keep_solution=True, shift_first_model_year=2005) assert ( - "Overriding keep_solution=True for shift_first_model_year" + "Override keep_solution=True for shift_first_model_year" == caplog.records[-1].message ) diff --git a/ixmp/tests/test_model.py b/ixmp/tests/test_model.py index a2d3e5a3b..8187decff 100644 --- a/ixmp/tests/test_model.py +++ b/ixmp/tests/test_model.py @@ -114,7 +114,7 @@ def test_filename_invalid_char(self, dantzig, char): # Indirectly test backend.write_file("….gdx") # This name_ keyword argument ends up received to GAMSModel.__init__ and sets # the GAMSModel.model_name attribute, and in turn the GDX file names used. - s.solve(name_=name) + s.solve(name_=name, quiet=True) @pytest.mark.parametrize( "kwargs", @@ -126,7 +126,8 @@ def test_filename_invalid_char(self, dantzig, char): ids=["null-comment", "null-list", "empty-list"], ) def test_GAMSModel_solve(test_data_path, dantzig, kwargs): - dantzig.clone().solve(**kwargs) + """Options to GAMSModel are handled without error.""" + dantzig.clone().solve(**kwargs, quiet=True) def test_error_message(self, test_data_path, test_mp): """GAMSModel.solve() displays a user-friendly message on error.""" diff --git a/ixmp/tests/test_utils.py b/ixmp/tests/test_utils.py index b65c15b4d..c41f09582 100644 --- a/ixmp/tests/test_utils.py +++ b/ixmp/tests/test_utils.py @@ -135,6 +135,11 @@ def test_diff_items(test_mp): pass # No check of the contents +def test_logger_deprecated(): + with pytest.warns(DeprecationWarning): + utils.logger() + + m_s = dict(model="m", scenario="s") URLS = [ diff --git a/ixmp/utils.py b/ixmp/utils.py index 35cf3dae1..5ac7cb361 100644 --- a/ixmp/utils.py +++ b/ixmp/utils.py @@ -5,6 +5,7 @@ from pathlib import Path from typing import Dict, Iterator, List, Tuple from urllib.parse import urlparse +from warnings import warn import pandas as pd @@ -12,18 +13,31 @@ log = logging.getLogger(__name__) -# globally accessible logger +# Globally accessible logger. +# TODO remove when :func:`logger` is removed. _LOGGER = None def logger(): - """Access global logger""" - global _LOGGER - if _LOGGER is None: - logging.basicConfig() - _LOGGER = logging.getLogger() - _LOGGER.setLevel("INFO") - return _LOGGER + """Access global logger. + + .. deprecated:: 3.3 + To control logging from ixmp, instead use :mod:`logging` to retrieve it: + + .. code-block:: python + + import logging + ixmp_logger = logging.getLogger("ixmp") + + # Example: set the level to INFO + ixmp_logger.setLevel(logging.INFO) + """ + warn( + "ixmp.utils.logger() is deprecated as of 3.3.0, and will be removed in ixmp " + '5.0. Use logging.getLogger("ixmp").', + DeprecationWarning, + ) + return logging.getLogger("ixmp") def as_str_list(arg, idx_names=None):