From 05cafcffd80ebb3813361345cc28ba73fd95bf64 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 5 Mar 2024 16:31:01 +0100 Subject: [PATCH 01/54] Expose .util.nodes_ex_world via .report.operator --- message_ix_models/report/operator.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/message_ix_models/report/operator.py b/message_ix_models/report/operator.py index 52fd2af0a5..2de6390d37 100644 --- a/message_ix_models/report/operator.py +++ b/message_ix_models/report/operator.py @@ -13,7 +13,7 @@ from iam_units.emissions import SPECIES from message_ix_models import Context -from message_ix_models.util import add_par_data +from message_ix_models.util import add_par_data, nodes_ex_world if TYPE_CHECKING: from pathlib import Path @@ -34,6 +34,7 @@ "gwp_factors", "make_output_path", "model_periods", + "nodes_ex_world", "remove_ts", "share_curtailment", ] From bf5e8c832c365d27905e83242348583fb7867650 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 5 Mar 2024 16:34:33 +0100 Subject: [PATCH 02/54] Use sdmx eval_annotation() in add_replacements() Warn of deprecation of eval_anno(). --- message_ix_models/report/util.py | 9 +++++---- message_ix_models/util/sdmx.py | 9 +++++++++ 2 files changed, 14 insertions(+), 4 deletions(-) diff --git a/message_ix_models/report/util.py b/message_ix_models/report/util.py index 62ba48a17f..39496a4d4c 100644 --- a/message_ix_models/report/util.py +++ b/message_ix_models/report/util.py @@ -10,8 +10,6 @@ from message_ix import Reporter from sdmx.model.v21 import Code -from message_ix_models.util import eval_anno - log = logging.getLogger(__name__) @@ -198,6 +196,9 @@ def copy_ts(rep: Reporter, other: str, filters: Optional[dict]) -> Key: def add_replacements(dim: str, codes: Iterable[Code]) -> None: """Update :data:`REPLACE_DIMS` for dimension `dim` with values from `codes`.""" for code in codes: - label = eval_anno(code, "report") - if label is not None: + try: + label = str(code.get_annotation(id="report").text) + except KeyError: + pass + else: REPLACE_DIMS[dim][f"{code.id.title()}$"] = label diff --git a/message_ix_models/util/sdmx.py b/message_ix_models/util/sdmx.py index 75e04c8cdf..e17b14b26d 100644 --- a/message_ix_models/util/sdmx.py +++ b/message_ix_models/util/sdmx.py @@ -1,10 +1,12 @@ """Utilities for handling objects from :mod:`sdmx`.""" + import logging from datetime import datetime from enum import Enum, Flag from importlib.metadata import version from pathlib import Path from typing import TYPE_CHECKING, Dict, List, Mapping, Optional, Union +from warnings import warn import sdmx import sdmx.message @@ -99,6 +101,13 @@ def eval_anno(obj: AnnotableArtefact, id: str): Use :meth:`sdmx.model.common.AnnotableArtefact.eval_annotation`, which provides the same functionality. """ + warn( + "message_ix_models.util.eval_anno; use sdmx.model.common.AnnotableArtefact" + ".eval_annotation() instead.", + DeprecationWarning, + stacklevel=2, + ) + try: value = str(obj.get_annotation(id=id).text) except KeyError: # No such attribute From 66df1988b0648ab04448d838e36b29ccda3ab06d Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 5 Mar 2024 16:36:06 +0100 Subject: [PATCH 03/54] Add SSP(2024) "release 3.0" data --- MANIFEST.in | 4 ++++ .../1706548837040-ssp_basic_drivers_release_3.0_full.csv.gz | 3 +++ 2 files changed, 7 insertions(+) create mode 100644 message_ix_models/data/ssp/1706548837040-ssp_basic_drivers_release_3.0_full.csv.gz diff --git a/MANIFEST.in b/MANIFEST.in index ae5bffc24a..46b272c504 100644 --- a/MANIFEST.in +++ b/MANIFEST.in @@ -3,4 +3,8 @@ prune message_ix_models/data/test/iea prune message_ix_models/data/test/MESSAGEix-GLOBIOM_1.1_R11_no-policy_baseline prune message_ix_models/data/test/ssp prune message_ix_models/data/water/* +# Larger package data +# - Not distributed on PyPI. +# - Should be fetched with Pooch from GitHub. +exclude message_ix_models/data/ssp/*.gz exclude message_ix_models/data/water/*.tar.xz diff --git a/message_ix_models/data/ssp/1706548837040-ssp_basic_drivers_release_3.0_full.csv.gz b/message_ix_models/data/ssp/1706548837040-ssp_basic_drivers_release_3.0_full.csv.gz new file mode 100644 index 0000000000..c7dece1260 --- /dev/null +++ b/message_ix_models/data/ssp/1706548837040-ssp_basic_drivers_release_3.0_full.csv.gz @@ -0,0 +1,3 @@ +version https://git-lfs.github.com/spec/v1 +oid sha256:1fffa5c7f87155d4476cd581771a496048e4e96cf4b59a7496cbb4f4fd79394f +size 20847285 From 7355da53504d786e94e9e8e08b0e1fa383e49fa2 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 5 Mar 2024 16:41:27 +0100 Subject: [PATCH 04/54] Adjust SSPUpdate class for SSP(2024) "release 3.0" Handle both the review-phase and release data structures. --- message_ix_models/project/ssp/data.py | 74 ++++++++++++++++++++------- message_ix_models/tools/exo_data.py | 1 + 2 files changed, 57 insertions(+), 18 deletions(-) diff --git a/message_ix_models/project/ssp/data.py b/message_ix_models/project/ssp/data.py index 2a585eb53b..3ce862895e 100644 --- a/message_ix_models/project/ssp/data.py +++ b/message_ix_models/project/ssp/data.py @@ -146,7 +146,7 @@ def __init__(self, source, source_kw): # Map the `measure` keyword to a string appearing in the data _kw = copy(source_kw) - self.measure = { + measure = { "GDP": "GDP|PPP", "POP": "Population", }[_kw.pop("measure")] @@ -154,24 +154,62 @@ def __init__(self, source, source_kw): # Store the model ID, if any self.model = _kw.pop("model", None) - if len(_kw): - raise ValueError(_kw) + # Identify the data release date/version/label + self.release = _kw.pop("release", "3.0") + + # Directories in which to locate `self.filename` + self.dirs = [] + + # Replacements to apply, if any + self.replace = {} + + # Prepare query pieces + models = [] + scenarios = [] + + if self.release == "3.0": + self.filename = "1706548837040-ssp_basic_drivers_release_3.0_full.csv.gz" + # Stored directly in message_ix_models + self.dirs.append(package_data_path("ssp")) + scenarios.append(f"SSP{self.ssp_number}") + + if measure == "GDP|PPP" and self.model != "OECD ENV-Growth 2023": + # Configure to prepend s="Historical Reference" observations to series + models.extend([self.model, "OECD ENV-Growth 2023"]) + scenarios.append("Historical Reference") + self.replace.update( + Model={"OECD ENV-Growth 2023": models[0]}, + Scenario={"Historical Reference": scenarios[0]}, + ) + elif self.release == "preview": + self.filename = "SSP-Review-Phase-1.csv.gz" + # Look first in message_data, then in message_ix_models test data + self.dirs.extend( + [private_data_path("ssp"), package_data_path("test", "ssp")] + ) + scenarios.append(f"SSP{self.ssp_number} - Review Phase 1") + else: + raise ValueError(f"{self.release = }") - def __call__(self): - # Assemble a query string - query = " and ".join( - [ - f"Scenario == 'SSP{self.ssp_number} - Review Phase 1'", - f"Variable == '{self.measure}'", - f"Model == '{self.model}'" if self.model else "True", - ] + # Assemble and store a query string + self.query = f"Scenario in {scenarios!r} and Variable == '{measure}'" + ( + f"and Model in {models!r}" if models else "" ) + # log.info(f"{self.query = }") - parts = ("ssp", "SSP-Review-Phase-1.csv.gz") - if HAS_MESSAGE_DATA: - path = private_data_path(*parts) - else: - path = package_data_path("test", *parts) - log.warning(f"Reading random data from {path}") + if len(_kw): + raise ValueError(_kw) - return iamc_like_data_for_query(path, query) + def __call__(self): + # Iterate over possible locations for self.filename + for dir in self.dirs: + path = dir.joinpath(self.filename) + if not path.exists(): + log.info(f"Not found: {path}") + elif "test" in path.parts: + log.warning(f"Reading random data from {path}") + else: + break + + # Use prepared query and replacements + return iamc_like_data_for_query(path, self.query, replace=self.replace) diff --git a/message_ix_models/tools/exo_data.py b/message_ix_models/tools/exo_data.py index 4c8ef0dfce..74b8e7327c 100644 --- a/message_ix_models/tools/exo_data.py +++ b/message_ix_models/tools/exo_data.py @@ -1,4 +1,5 @@ """Generic tools for working with exogenous data sources.""" + import logging from abc import ABC, abstractmethod from operator import itemgetter From 9ca3566bee3efff156dfb7900977f5eb318d082c Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Mon, 11 Mar 2024 10:28:48 +0100 Subject: [PATCH 05/54] Update internal usage of deprecated eval_anno() --- message_ix_models/model/bare.py | 5 +++-- message_ix_models/model/disutility.py | 13 +++++++------ message_ix_models/model/structure.py | 6 +++--- message_ix_models/util/scenarioinfo.py | 13 +++++++------ 4 files changed, 20 insertions(+), 17 deletions(-) diff --git a/message_ix_models/model/bare.py b/message_ix_models/model/bare.py index c5020341dc..9da3d4c348 100644 --- a/message_ix_models/model/bare.py +++ b/message_ix_models/model/bare.py @@ -8,7 +8,6 @@ import message_ix_models from message_ix_models import ScenarioInfo, Spec -from message_ix_models.util import eval_anno from .build import apply_spec from .config import Config @@ -134,7 +133,9 @@ def get_spec(context) -> Spec: add.set["commodity"] = get_codes("commodity") # Add units, associated with commodities - units = set(eval_anno(commodity, "unit") for commodity in add.set["commodity"]) + units = set( + commodity.eval_annotation(id="unit") for commodity in add.set["commodity"] + ) # Deduplicate by converting to a set and then back; not strictly necessary, # but reduces duplicate log entries add.set["unit"] = sorted(filter(None, units)) diff --git a/message_ix_models/model/disutility.py b/message_ix_models/model/disutility.py index 7ff71580f3..5325f3eb21 100644 --- a/message_ix_models/model/disutility.py +++ b/message_ix_models/model/disutility.py @@ -13,7 +13,6 @@ from message_ix_models.model.build import apply_spec from message_ix_models.util import ( broadcast, - eval_anno, make_io, make_matched_dfs, make_source_tech, @@ -81,9 +80,11 @@ def get_spec( fmt = dict(technology=t, group=g) # Format each field in the "input" and "output" annotations - input = {k: v.format(**fmt) for k, v in eval_anno(template, id="input").items()} + input = { + k: v.format(**fmt) for k, v in template.eval_annotation(id="input").items() + } output = { - k: v.format(**fmt) for k, v in eval_anno(template, id="output").items() + k: v.format(**fmt) for k, v in template.eval_annotation(id="output").items() } # - Format the ID string from the template @@ -176,8 +177,8 @@ def data_conversion(info, spec) -> MutableMapping[str, pd.DataFrame]: for t in technology: # Use the annotations on the technology Code to get information about the # commodity, level, and unit - input = eval_anno(t, "input") - output = eval_anno(t, "output") + input = t.eval_annotation(id="input") + output = t.eval_annotation(id="output") if None in (input, output): if t.id == "disutility source": continue # Data for this tech is from data_source() @@ -219,7 +220,7 @@ def data_source(info, spec) -> Mapping[str, pd.DataFrame]: # List of input levels where disutility commodity must exist levels = set() for t in spec["add"].set["technology"]: - input = eval_anno(t, "input") + input = t.eval_annotation(id="input") if input: levels.add(input["level"]) diff --git a/message_ix_models/model/structure.py b/message_ix_models/model/structure.py index 1539672a87..20d9d492f9 100644 --- a/message_ix_models/model/structure.py +++ b/message_ix_models/model/structure.py @@ -13,7 +13,7 @@ from iam_units import registry from sdmx.model.v21 import Annotation, Code, Codelist -from message_ix_models.util import eval_anno, load_package_data, package_data_path +from message_ix_models.util import load_package_data, package_data_path from message_ix_models.util.sdmx import as_codes log = logging.getLogger(__name__) @@ -126,7 +126,7 @@ def generate_product( attributes. """ # eval() and remove the original annotation - dims = eval_anno(template, "_generate") + dims = template.eval_annotation(id="_generate") template.pop_annotation(id="_generate") def _base(dim, match): @@ -191,7 +191,7 @@ def generate_set_elements(data: MutableMapping, name) -> None: if name in {"commodity", "technology"}: process_units_anno(name, code, quiet=True) - if eval_anno(code, "_generate"): + if code.eval_annotation(id="_generate"): # Requires a call to generate_product(); do these last deferred.append(code) continue diff --git a/message_ix_models/util/scenarioinfo.py b/message_ix_models/util/scenarioinfo.py index dba9926cbd..8a51f676c3 100644 --- a/message_ix_models/util/scenarioinfo.py +++ b/message_ix_models/util/scenarioinfo.py @@ -1,4 +1,5 @@ """:class:`ScenarioInfo` class.""" + import logging import re from collections import defaultdict @@ -11,7 +12,6 @@ import sdmx.model.v21 as sdmx_model from .ixmp import parse_url -from .sdmx import eval_anno if TYPE_CHECKING: from message_ix import Scenario @@ -235,13 +235,16 @@ def units_for(self, set_name: str, id: str) -> pint.Unit: -------- io_units """ + try: idx = self.set[set_name].index(id) except ValueError: print(self.set[set_name]) raise - return eval_anno(self.set[set_name][idx], "units") + return self.set[set_name][idx].eval_annotation( + id="units", globals=dict(registry=pint.get_application_registry()) + ) def io_units( self, technology: str, commodity: str, level: Optional[str] = None @@ -309,8 +312,6 @@ def year_from_codes(self, codes: List[sdmx_model.Code]): [2090, 2100, 2110] """ - from message_ix_models.util import eval_anno - # Clear existing values if len(self.set["year"]): log.debug(f"Discard existing 'year' elements: {repr(self.set['year'])}") @@ -333,7 +334,7 @@ def year_from_codes(self, codes: List[sdmx_model.Code]): self.set["year"].append(year) # Check for an annotation 'firstmodelyear: true' - if eval_anno(code, "firstmodelyear"): + if code.eval_annotation(id="firstmodelyear"): if fmy_set: # No coverage: data that triggers this should not be committed raise ValueError( # pragma: no cover @@ -349,7 +350,7 @@ def year_from_codes(self, codes: List[sdmx_model.Code]): duration_period.append( dict( year=year, - value=eval_anno(code, "duration_period") + value=code.eval_annotation(id="duration_period") or (year - duration_period[-1]["year"]), unit="y", ) From 1ed6cf53771bf830780b27b89ad5706145233f2b Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 03:53:41 +0100 Subject: [PATCH 06/54] Add .util.{datetime_now_with_tz,show_versions} --- message_ix_models/util/__init__.py | 23 +++++++++++++++++++++-- message_ix_models/util/ixmp.py | 9 ++++++++- 2 files changed, 29 insertions(+), 3 deletions(-) diff --git a/message_ix_models/util/__init__.py b/message_ix_models/util/__init__.py index a0209b311c..78dcebfd00 100644 --- a/message_ix_models/util/__init__.py +++ b/message_ix_models/util/__init__.py @@ -1,5 +1,6 @@ import logging from collections import ChainMap, defaultdict +from datetime import datetime from functools import partial, update_wrapper from importlib.metadata import version from itertools import count @@ -278,6 +279,12 @@ def copy_column(column_name): return lambda df: df[column_name] +def datetime_now_with_tz() -> datetime: + """Current date and time with time zone information.""" + tz = datetime.now().astimezone().tzinfo + return datetime.now(tz) + + def ffill( df: pd.DataFrame, dim: str, values: Sequence[CodeLike], expr: Optional[str] = None ) -> pd.DataFrame: @@ -321,8 +328,7 @@ def _maybe_eval(df): class KeyIterator(Protocol): - def __call__(self) -> "genno.Key": - ... + def __call__(self) -> "genno.Key": ... def iter_keys(base: "genno.Key") -> KeyIterator: @@ -664,6 +670,19 @@ def same_time(df: pd.DataFrame) -> pd.DataFrame: return df.assign(**{c: copy_column("time") for c in cols}) +def show_versions() -> str: + """Output of :func:`ixmp.show_versions`, as a :class:`str`.""" + from io import StringIO + + from . import ixmp + + # Retrieve package versions + buf = StringIO() + ixmp.show_versions(buf) + + return buf.getvalue() + + # FIXME Reduce complexity from 14 to ≤13 def strip_par_data( # noqa: C901 scenario: message_ix.Scenario, diff --git a/message_ix_models/util/ixmp.py b/message_ix_models/util/ixmp.py index f19f24afee..fe154eba1d 100644 --- a/message_ix_models/util/ixmp.py +++ b/message_ix_models/util/ixmp.py @@ -2,7 +2,13 @@ try: # ixmp 3.8.0 and later - from ixmp.util import discard_on_error, maybe_check_out, maybe_commit, parse_url + from ixmp.util import ( + discard_on_error, + maybe_check_out, + maybe_commit, + parse_url, + show_versions, + ) except ImportError: # ixmp <= 3.7.0 from contextlib import nullcontext @@ -11,6 +17,7 @@ maybe_check_out, maybe_commit, parse_url, + show_versions, ) def discard_on_error(*args): From 8d840c880bb85771ab10dafd4b13bea98f59ef7e Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 03:54:50 +0100 Subject: [PATCH 07/54] Broadcast outside loop in .disutility.data_conversion() Improves performance with pandas >= 2.2.0. --- message_ix_models/model/disutility.py | 23 ++++++++++++----------- 1 file changed, 12 insertions(+), 11 deletions(-) diff --git a/message_ix_models/model/disutility.py b/message_ix_models/model/disutility.py index 5325f3eb21..f4e8d2a267 100644 --- a/message_ix_models/model/disutility.py +++ b/message_ix_models/model/disutility.py @@ -3,11 +3,11 @@ from copy import copy from functools import partial from itertools import product -from typing import List, Mapping, MutableMapping, Sequence, Union +from typing import List, Mapping, MutableMapping, Sequence import message_ix import pandas as pd -from sdmx.model.v21 import Annotation, Code +from sdmx.model.common import Annotation, Code from message_ix_models import ScenarioInfo, Spec from message_ix_models.model.build import apply_spec @@ -23,8 +23,6 @@ log = logging.getLogger(__name__) -CodeLike = Union[str, Code] - def add( scenario: message_ix.Scenario, @@ -155,7 +153,7 @@ def func(df): return func -def data_conversion(info, spec) -> MutableMapping[str, pd.DataFrame]: +def data_conversion(info, spec: Spec) -> MutableMapping[str, pd.DataFrame]: """Generate input and output data for disutility conversion technologies.""" common = dict( mode="all", @@ -168,7 +166,7 @@ def data_conversion(info, spec) -> MutableMapping[str, pd.DataFrame]: ) # Use the spec to retrieve information - technology = spec["add"].set["technology"] + technology: List[Code] = spec.add.set["technology"] # Data to return data0: Mapping[str, List[pd.DataFrame]] = defaultdict(list) @@ -195,9 +193,6 @@ def data_conversion(info, spec) -> MutableMapping[str, pd.DataFrame]: **common, ) for par, df in i_o.items(): - # Broadcast across nodes - df = df.pipe(broadcast, node_loc=nodes_ex_world(info.N)).pipe(same_node) - if par == "input": # Add input of disutility df = pd.concat( @@ -206,8 +201,14 @@ def data_conversion(info, spec) -> MutableMapping[str, pd.DataFrame]: data0[par].append(df) - # Concatenate to a single data frame per parameter - data = {par: pd.concat(dfs, ignore_index=True) for par, dfs in data0.items()} + # - Concatenate to a single data frame per parameter + # - Broadcast across nodes + data = { + par: pd.concat(dfs, ignore_index=True) + .pipe(broadcast, node_loc=nodes_ex_world(info.N)) + .pipe(same_node) + for par, dfs in data0.items() + } # Create data for capacity_factor data.update(make_matched_dfs(base=data["input"], capacity_factor=1.0)) From 7afdb292c33312ba2e3d2940d63ff1006ac68d5a Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 03:55:42 +0100 Subject: [PATCH 08/54] Use platformdirs.user_cache_path in session_context --- message_ix_models/testing/__init__.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/message_ix_models/testing/__init__.py b/message_ix_models/testing/__init__.py index 27ffba9b2b..eeb025caa1 100644 --- a/message_ix_models/testing/__init__.py +++ b/message_ix_models/testing/__init__.py @@ -82,6 +82,8 @@ def session_context(pytestconfig, tmp_env): the :ref:`pytest tmp_path directory `. """ + from platformdirs import user_cache_path + ctx = Context.only() # Temporary, empty local directory for local data @@ -91,7 +93,7 @@ def session_context(pytestconfig, tmp_env): # pick up the existing setting from the user environment. If False, use a pytest- # managed cache directory that persists across test sessions. ctx.cache_path = ( - ctx.local_data.joinpath("cache") + user_cache_path("message-ix-models", ensure_exists=True) if pytestconfig.option.local_cache # TODO use pytestconfig.cache.mkdir() when pytest >= 6.3 is available else Path(pytestconfig.cache.makedir("cache")) From d3b370e62ab811ef6b5f3210e941d29500ea5944 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 03:57:19 +0100 Subject: [PATCH 09/54] Use platformdirs.user_cache_path in @cached() --- message_ix_models/util/cache.py | 17 ++++++++++------- 1 file changed, 10 insertions(+), 7 deletions(-) diff --git a/message_ix_models/util/cache.py b/message_ix_models/util/cache.py index e10ee7d9a5..f8ee880a6f 100644 --- a/message_ix_models/util/cache.py +++ b/message_ix_models/util/cache.py @@ -4,25 +4,29 @@ :mod:`message_ix_models`, so these can be used as arguments to cached functions and included in the computed cache key: -- :class:`sdmx.model.IdentifiableArtefact`, including :class:`.Code`: hashed as - their string representation / ID. +- :class:`sdmx.model.IdentifiableArtefact`, including :class:`.Code`: hashed as their + string representation / ID. - :class:`ixmp.Platform`, :class:`xarray.Dataset`: ignored, with a warning logged. - :class:`ScenarioInfo`: only the :attr:`~ScenarioInfo.set` entries are hashed. """ + import json import logging from dataclasses import asdict, is_dataclass -from typing import Callable +from typing import TYPE_CHECKING, Callable, Set import genno.caching import ixmp import sdmx.model import xarray as xr +from platformdirs import user_cache_path -from .context import Context from .scenarioinfo import ScenarioInfo +if TYPE_CHECKING: + from pathlib import Path + log = logging.getLogger(__name__) @@ -31,7 +35,7 @@ SKIP_CACHE = False # Paths already logged, to decrease verbosity -PATHS_SEEN = set() +PATHS_SEEN: Set["Path"] = set() # Show genno how to hash function arguments seen in message_ix_models @@ -73,8 +77,7 @@ def cached(func: Callable) -> Callable: :doc:`genno:cache` in the :mod:`genno` documentation """ # Determine and create the cache path - cache_path = Context.get_instance(-1).get_cache_path() - cache_path.mkdir(exist_ok=True, parents=True) + cache_path = user_cache_path("message-ix-models", ensure_exists=True) if cache_path not in PATHS_SEEN: log.debug(f"{func.__name__}() will cache in {cache_path}") From 895c6883356338344cfb368b1953fd3f3cf99c1f Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 03:57:50 +0100 Subject: [PATCH 10/54] Log show_versions() in workflow CLI command --- message_ix_models/workflow.py | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/message_ix_models/workflow.py b/message_ix_models/workflow.py index a627201294..0443529a47 100644 --- a/message_ix_models/workflow.py +++ b/message_ix_models/workflow.py @@ -1,4 +1,5 @@ """Tools for modeling workflows.""" + import logging import re from typing import ( @@ -320,6 +321,8 @@ def make_click_command(wf_callback: str, name: str, slug: str, **kwargs) -> "Com def _func(context, go, truncate_step, target_step, **kwargs): from importlib import import_module + from message_ix_models.util import show_versions + # Import the module and retrieve the callback function module_name, callback_name = wf_callback.rsplit(".", maxsplit=1) module = import_module(module_name) @@ -361,7 +364,8 @@ def _func(context, go, truncate_step, target_step, **kwargs): ) target_step = wf.default_key - log.info(f"Execute workflow:\n{wf.describe(target_step)}") + log.info(f"Execute workflow\n{wf.describe(target_step)}") + log.debug(f"…with package versions:\n{show_versions()}") if not go: path = context.get_local_path(f"{slug}-workflow.svg") From a95270e00413e45f01f2255446f93b8c1be5e0b7 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 03:59:53 +0100 Subject: [PATCH 11/54] Fix deprecated import in Context.handle_cli_args() --- message_ix_models/util/context.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/message_ix_models/util/context.py b/message_ix_models/util/context.py index 60c915902e..00c6453dec 100644 --- a/message_ix_models/util/context.py +++ b/message_ix_models/util/context.py @@ -1,4 +1,5 @@ """Context and settings for :mod:`message_ix_models` code.""" + import logging from copy import deepcopy from dataclasses import fields @@ -10,6 +11,7 @@ from click import BadOptionUsage from .config import Config +from .ixmp import parse_url log = logging.getLogger(__name__) @@ -371,7 +373,7 @@ def handle_cli_args( ) self.core.url = url - urlinfo = ixmp.utils.parse_url(url) + urlinfo = parse_url(url) platform_info.update(urlinfo[0]) scenario_info.update(urlinfo[1]) elif platform: From 0386a8a4c819ba29e4e90c24415619a6d9512d67 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 04:18:19 +0100 Subject: [PATCH 12/54] Improve logging - Handle logging in a separate thread for better performance. - Log to a file in the platformdirs.user_log_path() with a time stamp; this also captures show_versions() output. - Use distinct levels for file and console logging. - Absorb adjustments of third-party package logging from former pytest_sessionstart hook. - Avoid creating a log file on trivial or testing CLI invocations. --- message_ix_models/__init__.py | 4 +- message_ix_models/cli.py | 14 +- message_ix_models/testing/__init__.py | 11 -- message_ix_models/util/_logging.py | 197 +++++++++++++++++++------- 4 files changed, 160 insertions(+), 66 deletions(-) diff --git a/message_ix_models/__init__.py b/message_ix_models/__init__.py index 9c120879ef..ad8863248c 100644 --- a/message_ix_models/__init__.py +++ b/message_ix_models/__init__.py @@ -20,8 +20,8 @@ # Package is not installed __version__ = "999" -# No logging to stdout (console) by default -setup_logging(console=False) +# By default, no logging to console/stdout or to file +setup_logging(console=False, file=False) # Use iam_units.registry as the default pint.UnitsRegistry pint.set_application_registry(registry) diff --git a/message_ix_models/cli.py b/message_ix_models/cli.py index 508696dbcc..c94f06aed7 100644 --- a/message_ix_models/cli.py +++ b/message_ix_models/cli.py @@ -13,6 +13,7 @@ For more information, see https://docs.messageix.org/projects/models2/en/latest/cli.html """ + import logging import sys from pathlib import Path @@ -52,8 +53,17 @@ def main(click_ctx, **kwargs): # Start timer mark_time(quiet=True) - # Log to console - setup_logging(level="DEBUG" if kwargs.pop("verbose") else "INFO", console=True) + # Check for a non-trivial execution of the CLI + non_trivial = ( + not any(s in sys.argv for s in {"last-log", "--help"}) + and click_ctx.invoked_subcommand != "_test" + ) + + # Log to console: either DEBUG or INFO. + # Don't start file logging for a non-trivial execution. + setup_logging(level="DEBUG" if kwargs.pop("verbose") else "INFO", file=non_trivial) + + log.debug("CLI invoked with:\n" + "\n ".join(sys.argv)) # Store the most recently created instance of message_ix_models.Context. click # carries this object to any subcommand decorated with @click.pass_obj. diff --git a/message_ix_models/testing/__init__.py b/message_ix_models/testing/__init__.py index eeb025caa1..971e2fe2b1 100644 --- a/message_ix_models/testing/__init__.py +++ b/message_ix_models/testing/__init__.py @@ -48,17 +48,6 @@ def pytest_addoption(parser): ) -def pytest_sessionstart(): - # Quiet logs for some upstream packages - for name in ( - "graphviz._tools", - "pycountry.db", - "matplotlib.backends", - "matplotlib.font_manager", - ): - logging.getLogger(name).setLevel(logging.DEBUG + 1) - - # Fixtures diff --git a/message_ix_models/util/_logging.py b/message_ix_models/util/_logging.py index 63039b45a3..4778738518 100644 --- a/message_ix_models/util/_logging.py +++ b/message_ix_models/util/_logging.py @@ -1,10 +1,17 @@ """Logging utilities.""" +import atexit import logging import logging.config +import sys +import time from contextlib import contextmanager -from copy import deepcopy +from datetime import datetime, timedelta, timezone from time import process_time +from typing import TYPE_CHECKING, List, Union + +if TYPE_CHECKING: + import logging.handlers __all__ = [ "Formatter", @@ -87,7 +94,7 @@ class Formatter(logging.Formatter): _short_name = None - def __init__(self, colorama): + def __init__(self, colorama=None): super().__init__() if colorama: self.CYAN = colorama.Fore.CYAN @@ -152,67 +159,155 @@ def mark_time(quiet=False): ) +class StreamHandler(logging.StreamHandler): + """Like :class:`.logging.StreamHandler`, but refresh sys.stdout on each access. + + This avoids the case that :mod:`click`, :mod:`pytest`, or something else adjusts + :py:`sys.stdout` temporarily, but the handler's stored reference to the original is + not updated. + """ + + #: Name of the :mod:`sys` stream to use, as :class:`str` rather than a direct + #: reference. + stream_name: str + + def __init__(self, stream_name: str): + self.stream_name = stream_name + logging.Handler.__init__(self) + + @property + def stream(self): + return getattr(sys, self.stream_name) + + +class QueueHandler("logging.handlers.QueueHandler"): + """Queue handler with custom set-up. + + This emulates the default behaviour available in Python 3.12. + """ + + #: Corresponding listener that dispatches to the actual handlers. + listener: "logging.handlers.QueueListener" + + def __init__( + self, *, handlers: List[str] = [], respect_handler_level: bool = False + ) -> None: + from logging.handlers import QueueListener + from queue import SimpleQueue + + super().__init__(SimpleQueue()) + + # Construct the listener + # NB This relies on the non-public collection logging._handlers + self.listener = QueueListener( + self.queue, + *[logging._handlers[name] for name in handlers], # type: ignore [attr-defined] + respect_handler_level=respect_handler_level, + ) + + self.listener.start() + atexit.register(self.listener.stop) + + +# NB This is only separate to avoid complaints from mypy +HANDLER_CONFIG = dict( + console={ + "class": "message_ix_models.util._logging.StreamHandler", + "level": 99, + "formatter": "color", + "stream_name": "stdout", + }, + file={ + "class": "logging.FileHandler", + "level": 99, + "formatter": "plain", + "delay": True, + }, + queue={ + "class": "message_ix_models.util._logging.QueueHandler", + "handlers": ["console", "file"], + "respect_handler_level": True, + }, +) + + CONFIG = dict( version=1, disable_existing_loggers=False, - formatters=dict(simple={"()": "message_ix_models.util._logging.make_formatter"}), - handlers=dict( - console={ - "class": "logging.StreamHandler", - "level": "NOTSET", - "formatter": "simple", - "stream": "ext://sys.stdout", - }, - # commented: needs code in setup() to choose an appropriate file path - # file_handler={ - # "class": "logging.handlers.RotatingFileHandler", - # "level": "DEBUG", - # "formatter": "simple", - # "backupCount": "100", - # "delay": True, - # }, - ), - loggers=dict( - message_ix_models=dict( - level="NOTSET", - # propagate=False, - # handlers=[], - ), - message_data=dict( - level="NOTSET", - # propagate=False, - # handlers=[], - ), - ), - root=dict( - handlers=[], + formatters=dict( + color={"()": "message_ix_models.util._logging.make_formatter"}, + plain={"()": "message_ix_models.util._logging.Formatter"}, ), + handlers=HANDLER_CONFIG, + loggers={ + # Ensure no level set for these packages; the level of the "console"/"file" + # handlers determines outputs + "message_ix_models": dict(level=logging.NOTSET), + "message_data": dict(level=logging.NOTSET), + # Hide DEBUG messages for some upstream packages from the file log + "graphviz._tools": dict(level=logging.DEBUG + 1), + "pycountry.db": dict(level=logging.DEBUG + 1), + "matplotlib.backends": dict(level=logging.DEBUG + 1), + "matplotlib.font_manager": dict(level=logging.DEBUG + 1), + }, + root=dict(handlers=["queue"]), ) def setup( - level="NOTSET", - console=True, - # file=False, -): + level: Union[str, int] = 99, + console: bool = True, + *, + file: bool = False, +) -> None: """Initialize logging. Parameters ---------- level : str, *optional* - Log level for :mod:`message_ix_models` and :mod:`message_data`. + Log level for the console log handler. console : bool, *optional* - If :obj:`True`, print all messages to console using a :class:`Formatter`. + If :obj:`False`, do not print any messages to console. + file : bool, *optional* + If :obj:`False`, do not print any messages to file. """ - # Copy to avoid modifying with the operations below - config = deepcopy(CONFIG) - - config["root"].setdefault("level", level) - - if console: - config["root"]["handlers"].append("console") - # if file: - # config["loggers"]["message_data"]["handlers"].append("file") - - # Apply the configuration - logging.config.dictConfig(config) + from platformdirs import user_log_path + + # Construct the file name for the log file + filename = ( + datetime.now(timezone(timedelta(seconds=time.timezone))) + .isoformat(timespec="seconds") + .replace(":", "") + ) + log_dir = user_log_path("message-ix-models", ensure_exists=True) + HANDLER_CONFIG["file"].setdefault("filename", log_dir.joinpath(filename)) + CONFIG["handlers"] = HANDLER_CONFIG + + root = logging.getLogger() + if not root.handlers: + # Not yet configured → apply the configuration + logging.config.dictConfig(CONFIG) + + # Apply settings to loggers and handlers: either just-created, or pre-existing + + # Set the level of the console handler + get_handler("console").setLevel(99 if console is False else level) + + file_handler = get_handler("file") + if file is False: + file_handler.setLevel(99) + else: + file_handler.setLevel("DEBUG") + log.info(f"Log to {HANDLER_CONFIG['file']['filename']!s}") + + +def get_handler(name: str) -> logging.Handler: + """Retrieve one of the handlers of the :class:`logging.handlers.QueueListener`.""" + queue_handler = logging.getLogger().handlers[0] + assert isinstance(queue_handler, QueueHandler) + + for h in queue_handler.listener.handlers: + if h.name == name: + return h + + raise ValueError(name) From c0336098209dac0827dd8eda9a3aeb4e7473eab6 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 04:18:51 +0100 Subject: [PATCH 13/54] Add "last-log" CLI command --- message_ix_models/cli.py | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/message_ix_models/cli.py b/message_ix_models/cli.py index c94f06aed7..f40bc4d738 100644 --- a/message_ix_models/cli.py +++ b/message_ix_models/cli.py @@ -104,6 +104,17 @@ def export_test_data_cmd(ctx, exclude, nodes, techs): mark_time() +@main.command("last-log") +@click.pass_obj +def last_log(ctx): + """Show the location of the last log file, if any.""" + from platformdirs import user_log_path + + log_dir = user_log_path("message-ix-models") + if log_files := sorted(log_dir.glob("*T*")): + print(log_files[-1]) + + @main.command(hidden=True) @click.pass_obj def debug(ctx): From 69e70fd790fe14a815b83aa886d259466d4d712e Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 04:21:22 +0100 Subject: [PATCH 14/54] Tidy imports in .util._logging --- message_ix_models/util/_logging.py | 16 ++++++---------- 1 file changed, 6 insertions(+), 10 deletions(-) diff --git a/message_ix_models/util/_logging.py b/message_ix_models/util/_logging.py index 4778738518..07a5f36fe2 100644 --- a/message_ix_models/util/_logging.py +++ b/message_ix_models/util/_logging.py @@ -3,15 +3,14 @@ import atexit import logging import logging.config +import logging.handlers import sys import time from contextlib import contextmanager from datetime import datetime, timedelta, timezone +from queue import SimpleQueue from time import process_time -from typing import TYPE_CHECKING, List, Union - -if TYPE_CHECKING: - import logging.handlers +from typing import List, Union __all__ = [ "Formatter", @@ -180,26 +179,23 @@ def stream(self): return getattr(sys, self.stream_name) -class QueueHandler("logging.handlers.QueueHandler"): +class QueueHandler(logging.handlers.QueueHandler): """Queue handler with custom set-up. This emulates the default behaviour available in Python 3.12. """ #: Corresponding listener that dispatches to the actual handlers. - listener: "logging.handlers.QueueListener" + listener: logging.handlers.QueueListener def __init__( self, *, handlers: List[str] = [], respect_handler_level: bool = False ) -> None: - from logging.handlers import QueueListener - from queue import SimpleQueue - super().__init__(SimpleQueue()) # Construct the listener # NB This relies on the non-public collection logging._handlers - self.listener = QueueListener( + self.listener = logging.handlers.QueueListener( self.queue, *[logging._handlers[name] for name in handlers], # type: ignore [attr-defined] respect_handler_level=respect_handler_level, From ddc74e02aa6df74503d0c555103525b2a1b469bb Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 04:37:55 +0100 Subject: [PATCH 15/54] Adjust use of eval_anno() in tests --- message_ix_models/tests/model/test_structure.py | 9 +++++---- message_ix_models/tests/util/test_sdmx.py | 12 ++++++++---- 2 files changed, 13 insertions(+), 8 deletions(-) diff --git a/message_ix_models/tests/model/test_structure.py b/message_ix_models/tests/model/test_structure.py index 8c0fef4777..e9724d05b8 100644 --- a/message_ix_models/tests/model/test_structure.py +++ b/message_ix_models/tests/model/test_structure.py @@ -15,7 +15,7 @@ process_commodity_codes, process_units_anno, ) -from message_ix_models.util import as_codes, eval_anno +from message_ix_models.util import as_codes @pytest.mark.parametrize( @@ -97,8 +97,9 @@ def test_commodities(self): assert check in data # Units for one commodity can be retrieved and parsed + g = dict(registry=registry) coal = data[data.index("coal")] - assert isinstance(eval_anno(coal, "units"), registry.Unit) + assert isinstance(coal.eval_annotation("units", globals=g), registry.Unit) # Descriptions are parsed without new lines crudeoil = data[data.index("crudeoil")] @@ -107,7 +108,7 @@ def test_commodities(self): # Processing a second time does not double-wrap the unit expressions process_commodity_codes(data) coal = data[data.index("coal")] - assert isinstance(eval_anno(coal, "units"), registry.Unit) + assert isinstance(coal.eval_annotation("units", globals=g), registry.Unit) def test_levels(self): data = get_codes("level") @@ -277,4 +278,4 @@ def test_process_units_anno(): process_units_anno("", codes[0]) # Parents' units are propagated to the child - assert registry.Unit("kg") == eval_anno(codes[1], "units") + assert registry.Unit("kg") == codes[1].eval_annotation("units") diff --git a/message_ix_models/tests/util/test_sdmx.py b/message_ix_models/tests/util/test_sdmx.py index 16fb946be4..febea39234 100644 --- a/message_ix_models/tests/util/test_sdmx.py +++ b/message_ix_models/tests/util/test_sdmx.py @@ -7,14 +7,17 @@ from message_ix_models.util.sdmx import eval_anno, make_enum, read -def test_eval_anno(caplog): +def test_eval_anno(caplog, recwarn): c = Code() - assert None is eval_anno(c, "foo") + with pytest.warns(DeprecationWarning): + assert None is eval_anno(c, "foo") c.annotations.append(Annotation(id="foo", text="bar baz")) - with caplog.at_level(logging.DEBUG, logger="message_ix_models"): + with caplog.at_level(logging.DEBUG, logger="message_ix_models"), pytest.warns( + DeprecationWarning + ): assert "bar baz" == eval_anno(c, "foo") assert re.fullmatch( @@ -23,7 +26,8 @@ def test_eval_anno(caplog): c.annotations.append(Annotation(id="qux", text="3 + 4")) - assert 7 == eval_anno(c, id="qux") + with pytest.warns(DeprecationWarning): + assert 7 == eval_anno(c, id="qux") def test_make_enum(): From ea686a9643b3dbf3a8e657a8e0c9d2737ae4afc2 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 04:52:52 +0100 Subject: [PATCH 16/54] Read cache path from core Config class --- message_ix_models/util/cache.py | 6 +++--- message_ix_models/util/config.py | 9 ++++++++- message_ix_models/util/context.py | 10 ++-------- 3 files changed, 13 insertions(+), 12 deletions(-) diff --git a/message_ix_models/util/cache.py b/message_ix_models/util/cache.py index f8ee880a6f..389d2dec5d 100644 --- a/message_ix_models/util/cache.py +++ b/message_ix_models/util/cache.py @@ -8,7 +8,6 @@ string representation / ID. - :class:`ixmp.Platform`, :class:`xarray.Dataset`: ignored, with a warning logged. - :class:`ScenarioInfo`: only the :attr:`~ScenarioInfo.set` entries are hashed. - """ import json @@ -20,8 +19,8 @@ import ixmp import sdmx.model import xarray as xr -from platformdirs import user_cache_path +from .context import Context from .scenarioinfo import ScenarioInfo if TYPE_CHECKING: @@ -77,11 +76,12 @@ def cached(func: Callable) -> Callable: :doc:`genno:cache` in the :mod:`genno` documentation """ # Determine and create the cache path - cache_path = user_cache_path("message-ix-models", ensure_exists=True) + cache_path = Context.get_instance(-1).core.cache_path if cache_path not in PATHS_SEEN: log.debug(f"{func.__name__}() will cache in {cache_path}") PATHS_SEEN.add(cache_path) + cache_path.mkdir(parents=True, exist_ok=True) # Use the genno internals to wrap the function. cached_load = genno.caching.decorate( diff --git a/message_ix_models/util/config.py b/message_ix_models/util/config.py index a467736e93..c25d1a42c6 100644 --- a/message_ix_models/util/config.py +++ b/message_ix_models/util/config.py @@ -165,7 +165,8 @@ class Config: dest: Optional[str] = None #: Base path for cached data, e.g. as given by the :program:`--cache-path` CLI - #: option. Default: :file:`{local_data}/cache/`. + #: option. Default: the directory :file:`message-ix-models` within the directory + #: given by :func:`.platformdirs.user_cache_path`. cache_path: Optional[str] = None #: Paths of files containing debug outputs. See :meth:`Context.write_debug_archive`. @@ -179,3 +180,9 @@ class Config: #: Flag for causing verbose output to logs or stdout. Different modules will respect #: :attr:`verbose` in distinct ways. verbose: bool = False + + def __post_init__(self): + if self.cache_path is None: + from platformdirs import user_cache_path + + self.cache_path = user_cache_path("message-ix-models", ensure_exists=True) diff --git a/message_ix_models/util/context.py b/message_ix_models/util/context.py index 00c6453dec..0182701ef8 100644 --- a/message_ix_models/util/context.py +++ b/message_ix_models/util/context.py @@ -271,14 +271,8 @@ def get_cache_path(self, *parts) -> Path: The directory containing the resulting path is created if it does not already exist. """ - # Construct relative to local_data if cache_path is not defined - base = self.core.cache_path or self.core.local_data.joinpath("cache") - - result = base.joinpath(*parts) - - # Ensure the directory exists - result.parent.mkdir(parents=True, exist_ok=True) - + result = self.core.cache_path.joinpath(*parts) + result.parent.mkdir(parents=True, exist_ok=True) # Ensure the directory exists return result def get_local_path(self, *parts: str, suffix=None) -> Path: From 23002532ad964938e1584ca2f52923c6ddf27beb Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 10:31:24 +0100 Subject: [PATCH 17/54] Add ExoDataSource.raise_on_extra_kw() - Helper method for subclasses. - Also, deepcopy() source_kw for possibly destructive manipulation in subclass __init__(). --- message_ix_models/tools/exo_data.py | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/message_ix_models/tools/exo_data.py b/message_ix_models/tools/exo_data.py index 74b8e7327c..78ff487abf 100644 --- a/message_ix_models/tools/exo_data.py +++ b/message_ix_models/tools/exo_data.py @@ -2,6 +2,7 @@ import logging from abc import ABC, abstractmethod +from copy import deepcopy from operator import itemgetter from pathlib import Path from typing import Any, Dict, Literal, Mapping, Optional, Tuple, Type @@ -112,6 +113,15 @@ def transform(self, c: "Computer", base_key: Key) -> Key: return k2 + def raise_on_extra_kw(self, kwargs) -> None: + """Helper for subclasses.""" + if len(kwargs): + log.error( + f"Unhandled extra keyword arguments for {type(self).__name__}: " + + repr(kwargs) + ) + raise ValueError(kwargs) + def prepare_computer( context, @@ -164,7 +174,7 @@ def prepare_computer( for cls in SOURCES.values(): try: # Instantiate a Source object to provide this data - source_obj = cls(source, source_kw or dict()) + source_obj = cls(source, deepcopy(source_kw or dict())) except Exception: pass # Class does not recognize the arguments From 3d1b2d28517d20cefd86938d8b665136f73c8529 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 10:36:10 +0100 Subject: [PATCH 18/54] Combine _logging.make_formatter and Formatter --- message_ix_models/util/__init__.py | 4 +++ message_ix_models/util/_logging.py | 52 ++++++++++++------------------ 2 files changed, 25 insertions(+), 31 deletions(-) diff --git a/message_ix_models/util/__init__.py b/message_ix_models/util/__init__.py index 78dcebfd00..87a77f5776 100644 --- a/message_ix_models/util/__init__.py +++ b/message_ix_models/util/__init__.py @@ -22,6 +22,7 @@ import pint from ._convert_units import convert_units, series_of_pint_quantity +from ._logging import mark_time, preserve_log_level, silence_log from .cache import cached from .common import ( HAS_MESSAGE_DATA, @@ -68,15 +69,18 @@ "make_io", "make_matched_dfs", "make_source_tech", + "mark_time", "maybe_query", "merge_data", "minimum_version", "package_data_path", + "preserve_log_level", "private_data_path", "replace_par_data", "same_node", "same_time", "series_of_pint_quantity", + "silence_log", "strip_par_data", ] diff --git a/message_ix_models/util/_logging.py b/message_ix_models/util/_logging.py index 07a5f36fe2..74a3901c0b 100644 --- a/message_ix_models/util/_logging.py +++ b/message_ix_models/util/_logging.py @@ -12,11 +12,10 @@ from time import process_time from typing import List, Union +# NB mark_time, preserve_log_level, and silence_log are exposed by util/__init__.py __all__ = [ "Formatter", - "make_formatter", "setup", - "silence_log", ] log = logging.getLogger(__name__) @@ -83,8 +82,9 @@ class Formatter(logging.Formatter): Parameters ---------- - colorama : module - If provided, :mod:`colorama` is used to colour log messages printed to stdout. + use_color : bool, *optional* + If :any:`True`, :mod:`colorama` is used to colour log messages printed to + stdout. """ CYAN = "" @@ -93,12 +93,20 @@ class Formatter(logging.Formatter): _short_name = None - def __init__(self, colorama=None): + def __init__(self, use_colour: bool = True): super().__init__() - if colorama: - self.CYAN = colorama.Fore.CYAN - self.DIM = colorama.Style.DIM - self.RESET_ALL = colorama.Style.RESET_ALL + + try: + if use_colour: + # Import and initialize colorama + import colorama + + colorama.init() + self.CYAN = colorama.Fore.CYAN + self.DIM = colorama.Style.DIM + self.RESET_ALL = colorama.Style.RESET_ALL + except ImportError: # pragma: no cover + pass # Not installed def format(self, record): """Format `record`. @@ -127,29 +135,11 @@ def format(self, record): return f"{prefix}{record.funcName}{self.RESET_ALL} {record.getMessage()}" -def make_formatter(): - """Return a :class:`Formatter` instance for the ``message_ix_models`` logger. - - See also - -------- - setup - """ - try: - # Initialize colorama - import colorama - - colorama.init() - except ImportError: # pragma: no cover - # Colorama not installed - colorama = None - - return Formatter(colorama) - - +# For mark_time() _TIMES = [] -def mark_time(quiet=False): +def mark_time(quiet: bool = False) -> None: """Record and log (if `quiet` is :obj:`True`) a time mark.""" _TIMES.append(process_time()) if not quiet and len(_TIMES) > 1: @@ -231,8 +221,8 @@ def __init__( version=1, disable_existing_loggers=False, formatters=dict( - color={"()": "message_ix_models.util._logging.make_formatter"}, - plain={"()": "message_ix_models.util._logging.Formatter"}, + color={"()": "message_ix_models.util._logging.Formatter"}, + plain={"()": "message_ix_models.util._logging.Formatter", "use_colour": False}, ), handlers=HANDLER_CONFIG, loggers={ From 59e5f807891a2c2f4b52b17401c65f04c74998db Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 10:40:33 +0100 Subject: [PATCH 19/54] Sort .util._logging - Globals, classes, functions. - Alphabetize. --- message_ix_models/util/_logging.py | 270 ++++++++++++++--------------- 1 file changed, 135 insertions(+), 135 deletions(-) diff --git a/message_ix_models/util/_logging.py b/message_ix_models/util/_logging.py index 74a3901c0b..b33211635e 100644 --- a/message_ix_models/util/_logging.py +++ b/message_ix_models/util/_logging.py @@ -15,66 +15,59 @@ # NB mark_time, preserve_log_level, and silence_log are exposed by util/__init__.py __all__ = [ "Formatter", + "QueueHandler", + "StreamHandler", "setup", ] log = logging.getLogger(__name__) - -@contextmanager -def silence_log(names=None, level=logging.ERROR): - """Context manager to temporarily quiet 1 or more loggers. - - Parameters - ---------- - names : str, *optional* - Space-separated names of loggers to quiet. - level : int, *optional* - Minimum level of log messages to allow. - - Examples - -------- - >>> with silence_log(): - >>> log.warning("This message is not recorded.") - """ - # Default: the top-level logger for the package containing this file - if names is None: - names = [__name__.split(".")[0], "message_data"] - elif isinstance(names, str): - names = [names] - - log.info(f"Set level={level} for logger(s): {' '.join(names)}") - - # Retrieve the logger objects - loggers = list(map(logging.getLogger, names)) - # Store their current levels - levels = [] - - try: - for logger in loggers: - levels.append(logger.getEffectiveLevel()) # Store the current levels - logger.setLevel(level) # Set the level - yield - finally: - # Restore the levels - for logger, original_level in zip(loggers, levels): - logger.setLevel(original_level) - log.info("…restored.") +# NB This is only separate to avoid complaints from mypy +_HANDLER_CONFIG = dict( + console={ + "class": "message_ix_models.util._logging.StreamHandler", + "level": 99, + "formatter": "color", + "stream_name": "stdout", + }, + file={ + "class": "logging.FileHandler", + "level": 99, + "formatter": "plain", + "delay": True, + }, + queue={ + "class": "message_ix_models.util._logging.QueueHandler", + "handlers": ["console", "file"], + "respect_handler_level": True, + }, +) -@contextmanager -def preserve_log_level(): - """Context manager to preserve the level of the ``message_ix_models`` logger.""" - # Get the top-level logger for the package containing this file - main_log = logging.getLogger(__name__.split(".")[0]) +_CONFIG = dict( + version=1, + disable_existing_loggers=False, + formatters=dict( + color={"()": "message_ix_models.util._logging.Formatter"}, + plain={"()": "message_ix_models.util._logging.Formatter", "use_colour": False}, + ), + handlers=_HANDLER_CONFIG, + loggers={ + # Ensure no level set for these packages; the level of the "console"/"file" + # handlers determines outputs + "message_ix_models": dict(level=logging.NOTSET), + "message_data": dict(level=logging.NOTSET), + # Hide DEBUG messages for some upstream packages from the file log + "graphviz._tools": dict(level=logging.DEBUG + 1), + "pycountry.db": dict(level=logging.DEBUG + 1), + "matplotlib.backends": dict(level=logging.DEBUG + 1), + "matplotlib.font_manager": dict(level=logging.DEBUG + 1), + }, + root=dict(handlers=["queue"]), +) - try: - # Store the current level - level = main_log.getEffectiveLevel() - yield - finally: - # Restore the level - main_log.setLevel(level) +# For mark_time() +_TIMES = [] class Formatter(logging.Formatter): @@ -135,18 +128,31 @@ def format(self, record): return f"{prefix}{record.funcName}{self.RESET_ALL} {record.getMessage()}" -# For mark_time() -_TIMES = [] +class QueueHandler(logging.handlers.QueueHandler): + """Queue handler with custom set-up. + This emulates the default behaviour available in Python 3.12. + """ -def mark_time(quiet: bool = False) -> None: - """Record and log (if `quiet` is :obj:`True`) a time mark.""" - _TIMES.append(process_time()) - if not quiet and len(_TIMES) > 1: - logging.getLogger(__name__).info( - f" +{_TIMES[-1] - _TIMES[-2]:.1f} = {_TIMES[-1]:.1f} seconds" + #: Corresponding listener that dispatches to the actual handlers. + listener: logging.handlers.QueueListener + + def __init__( + self, *, handlers: List[str] = [], respect_handler_level: bool = False + ) -> None: + super().__init__(SimpleQueue()) + + # Construct the listener + # NB This relies on the non-public collection logging._handlers + self.listener = logging.handlers.QueueListener( + self.queue, + *[logging._handlers[name] for name in handlers], # type: ignore [attr-defined] + respect_handler_level=respect_handler_level, ) + self.listener.start() + atexit.register(self.listener.stop) + class StreamHandler(logging.StreamHandler): """Like :class:`.logging.StreamHandler`, but refresh sys.stdout on each access. @@ -169,75 +175,40 @@ def stream(self): return getattr(sys, self.stream_name) -class QueueHandler(logging.handlers.QueueHandler): - """Queue handler with custom set-up. +def _get_handler(name: str) -> logging.Handler: + """Retrieve one of the handlers of the :class:`logging.handlers.QueueListener`.""" + queue_handler = logging.getLogger().handlers[0] + assert isinstance(queue_handler, QueueHandler) - This emulates the default behaviour available in Python 3.12. - """ + for h in queue_handler.listener.handlers: + if h.name == name: + return h - #: Corresponding listener that dispatches to the actual handlers. - listener: logging.handlers.QueueListener + raise ValueError(name) - def __init__( - self, *, handlers: List[str] = [], respect_handler_level: bool = False - ) -> None: - super().__init__(SimpleQueue()) - # Construct the listener - # NB This relies on the non-public collection logging._handlers - self.listener = logging.handlers.QueueListener( - self.queue, - *[logging._handlers[name] for name in handlers], # type: ignore [attr-defined] - respect_handler_level=respect_handler_level, +def mark_time(quiet: bool = False) -> None: + """Record and log (if `quiet` is :obj:`True`) a time mark.""" + _TIMES.append(process_time()) + if not quiet and len(_TIMES) > 1: + logging.getLogger(__name__).info( + f" +{_TIMES[-1] - _TIMES[-2]:.1f} = {_TIMES[-1]:.1f} seconds" ) - self.listener.start() - atexit.register(self.listener.stop) - - -# NB This is only separate to avoid complaints from mypy -HANDLER_CONFIG = dict( - console={ - "class": "message_ix_models.util._logging.StreamHandler", - "level": 99, - "formatter": "color", - "stream_name": "stdout", - }, - file={ - "class": "logging.FileHandler", - "level": 99, - "formatter": "plain", - "delay": True, - }, - queue={ - "class": "message_ix_models.util._logging.QueueHandler", - "handlers": ["console", "file"], - "respect_handler_level": True, - }, -) +@contextmanager +def preserve_log_level(): + """Context manager to preserve the level of the ``message_ix_models`` logger.""" + # Get the top-level logger for the package containing this file + main_log = logging.getLogger(__name__.split(".")[0]) -CONFIG = dict( - version=1, - disable_existing_loggers=False, - formatters=dict( - color={"()": "message_ix_models.util._logging.Formatter"}, - plain={"()": "message_ix_models.util._logging.Formatter", "use_colour": False}, - ), - handlers=HANDLER_CONFIG, - loggers={ - # Ensure no level set for these packages; the level of the "console"/"file" - # handlers determines outputs - "message_ix_models": dict(level=logging.NOTSET), - "message_data": dict(level=logging.NOTSET), - # Hide DEBUG messages for some upstream packages from the file log - "graphviz._tools": dict(level=logging.DEBUG + 1), - "pycountry.db": dict(level=logging.DEBUG + 1), - "matplotlib.backends": dict(level=logging.DEBUG + 1), - "matplotlib.font_manager": dict(level=logging.DEBUG + 1), - }, - root=dict(handlers=["queue"]), -) + try: + # Store the current level + level = main_log.getEffectiveLevel() + yield + finally: + # Restore the level + main_log.setLevel(level) def setup( @@ -266,34 +237,63 @@ def setup( .replace(":", "") ) log_dir = user_log_path("message-ix-models", ensure_exists=True) - HANDLER_CONFIG["file"].setdefault("filename", log_dir.joinpath(filename)) - CONFIG["handlers"] = HANDLER_CONFIG + _HANDLER_CONFIG["file"].setdefault("filename", log_dir.joinpath(filename)) + _CONFIG["handlers"] = _HANDLER_CONFIG root = logging.getLogger() if not root.handlers: # Not yet configured → apply the configuration - logging.config.dictConfig(CONFIG) + logging.config.dictConfig(_CONFIG) # Apply settings to loggers and handlers: either just-created, or pre-existing # Set the level of the console handler - get_handler("console").setLevel(99 if console is False else level) + _get_handler("console").setLevel(99 if console is False else level) - file_handler = get_handler("file") + file_handler = _get_handler("file") if file is False: file_handler.setLevel(99) else: file_handler.setLevel("DEBUG") - log.info(f"Log to {HANDLER_CONFIG['file']['filename']!s}") + log.info(f"Log to {_HANDLER_CONFIG['file']['filename']!s}") -def get_handler(name: str) -> logging.Handler: - """Retrieve one of the handlers of the :class:`logging.handlers.QueueListener`.""" - queue_handler = logging.getLogger().handlers[0] - assert isinstance(queue_handler, QueueHandler) +@contextmanager +def silence_log(names=None, level=logging.ERROR): + """Context manager to temporarily quiet 1 or more loggers. - for h in queue_handler.listener.handlers: - if h.name == name: - return h + Parameters + ---------- + names : str, *optional* + Space-separated names of loggers to quiet. + level : int, *optional* + Minimum level of log messages to allow. - raise ValueError(name) + Examples + -------- + >>> with silence_log(): + >>> log.warning("This message is not recorded.") + """ + # Default: the top-level logger for the package containing this file + if names is None: + names = [__name__.split(".")[0], "message_data"] + elif isinstance(names, str): + names = [names] + + log.info(f"Set level={level} for logger(s): {' '.join(names)}") + + # Retrieve the logger objects + loggers = list(map(logging.getLogger, names)) + # Store their current levels + levels = [] + + try: + for logger in loggers: + levels.append(logger.getEffectiveLevel()) # Store the current levels + logger.setLevel(level) # Set the level + yield + finally: + # Restore the levels + for logger, original_level in zip(loggers, levels): + logger.setLevel(original_level) + log.info("…restored.") From 3fea01ec1a53b190a204c97c30bbd577599b225f Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 10:40:53 +0100 Subject: [PATCH 20/54] Don't log CLI args within pytest --- message_ix_models/cli.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/message_ix_models/cli.py b/message_ix_models/cli.py index f40bc4d738..31d52825e8 100644 --- a/message_ix_models/cli.py +++ b/message_ix_models/cli.py @@ -63,7 +63,8 @@ def main(click_ctx, **kwargs): # Don't start file logging for a non-trivial execution. setup_logging(level="DEBUG" if kwargs.pop("verbose") else "INFO", file=non_trivial) - log.debug("CLI invoked with:\n" + "\n ".join(sys.argv)) + if "pytest" not in sys.argv[0]: + log.debug("CLI invoked with:\n" + "\n ".join(sys.argv)) # Store the most recently created instance of message_ix_models.Context. click # carries this object to any subcommand decorated with @click.pass_obj. From 4b56c50f1fbd254f165b74b90f9286952da2e123 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 10:43:32 +0100 Subject: [PATCH 21/54] Add sort=True to some pd.concat() calls MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Suppress warnings with pandas >= 2.2.0 - Bump ruff v0.1.13 → v0.3.0 in pre-commit config. --- .pre-commit-config.yaml | 2 +- message_ix_models/tests/test_report.py | 1 + message_ix_models/util/__init__.py | 6 ++++-- 3 files changed, 6 insertions(+), 3 deletions(-) diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index add115b000..2d531248e9 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -20,7 +20,7 @@ repos: - "message-ix @ git+https://github.com/iiasa/message_ix.git@main" args: ["."] - repo: https://github.com/astral-sh/ruff-pre-commit - rev: v0.1.13 + rev: v0.3.0 hooks: - id: ruff - id: ruff-format diff --git a/message_ix_models/tests/test_report.py b/message_ix_models/tests/test_report.py index 1fdf351f1d..4f8e507ece 100644 --- a/message_ix_models/tests/test_report.py +++ b/message_ix_models/tests/test_report.py @@ -1,4 +1,5 @@ """Tests for :mod:`message_ix_models.report`.""" + from importlib.metadata import version import numpy as np diff --git a/message_ix_models/util/__init__.py b/message_ix_models/util/__init__.py index 87a77f5776..e5dd980fc9 100644 --- a/message_ix_models/util/__init__.py +++ b/message_ix_models/util/__init__.py @@ -214,7 +214,9 @@ def _check_dim(d): _check_dim(dim) # Concatenate 1 copy of `df` for each row in `labels` df = pd.concat( - [df.assign(**row) for _, row in labels.iterrows()], ignore_index=True + [df.assign(**row) for _, row in labels.iterrows()], + ignore_index=True, + sort=False, ) # Next, broadcast other dimensions given as keyword arguments @@ -231,7 +233,7 @@ def _check_dim(d): # - Re-add the column from the constructed MultiIndex # - Reindex for sequential row numbers df = ( - pd.concat([df] * len(levels), keys=levels, names=[dim]) + pd.concat([df] * len(levels), keys=levels, names=[dim], sort=False) .drop(dim, axis=1) .reset_index(dim) .reset_index(drop=True) From 8200fe89d6d936d47c1c68b529f71d3a5d018714 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 10:49:28 +0100 Subject: [PATCH 22/54] Improve SSP{Original,Update} data providers - Pre-compute all arguments used in __call__(). - Don't store as class variables anything ephemeral. - Align & simplify path logic. - Use raise_on_extra_kw(). --- message_ix_models/project/ssp/data.py | 140 ++++++++++++++------------ 1 file changed, 73 insertions(+), 67 deletions(-) diff --git a/message_ix_models/project/ssp/data.py b/message_ix_models/project/ssp/data.py index 3ce862895e..93aa0fd112 100644 --- a/message_ix_models/project/ssp/data.py +++ b/message_ix_models/project/ssp/data.py @@ -1,16 +1,11 @@ import logging -from copy import copy from message_ix_models.tools.exo_data import ( ExoDataSource, iamc_like_data_for_query, register_source, ) -from message_ix_models.util import ( - HAS_MESSAGE_DATA, - package_data_path, - private_data_path, -) +from message_ix_models.util import package_data_path, private_data_path __all__ = [ "SSPOriginal", @@ -56,6 +51,9 @@ class SSPOriginal(ExoDataSource): id = "SSP" + #: Name of file containing the data. + filename = "SspDb_country_data_2013-06-12.csv.zip" + #: One-to-one correspondence between "model" codes and date fragments in scenario #: codes. model_date = { @@ -74,44 +72,45 @@ def __init__(self, source, source_kw): if not source.startswith(s): raise ValueError(source) - *parts, self.ssp_number = source.partition(s) + *parts, ssp_id = source.partition(s) # Map the `measure` keyword to a string appearing in the data - _kw = copy(source_kw) - self.measure = { + measure = { "GDP": "GDP|PPP", "POP": "Population", - }[_kw.pop("measure")] + }[source_kw.pop("measure")] # Store the model ID, if any - self.model = _kw.pop("model", None) + model = source_kw.pop("model", None) # Determine the date based on the model ID. There is a 1:1 correspondence. - self.date = self.model_date[self.model] + date = self.model_date[model] - if len(_kw): - raise ValueError(_kw) + self.raise_on_extra_kw(source_kw) - def __call__(self): # Assemble a query string - extra = "d" if self.ssp_number == "4" and self.model == "IIASA-WiC POP" else "" - query = " and ".join( - [ - f"SCENARIO == 'SSP{self.ssp_number}{extra}_v9_{self.date}'", - f"VARIABLE == '{self.measure}'", - f"MODEL == '{self.model}'" if self.model else "True", - ] + extra = "d" if ssp_id == "4" and model == "IIASA-WiC POP" else "" + self.query = ( + f"SCENARIO == 'SSP{ssp_id}{extra}_v9_{date}' and VARIABLE == '{measure}'" + + (f" and MODEL == '{model}'" if model else "") ) - log.debug(query) + # log.debug(query) - parts = ("ssp", "SspDb_country_data_2013-06-12.csv.zip") - if HAS_MESSAGE_DATA: - path = private_data_path(*parts) - else: - path = package_data_path("test", *parts) - log.warning(f"Reading random data from {path}") + # Iterate over possible locations for the data file + dirs = [private_data_path("ssp"), package_data_path("test", "ssp")] + for path in [d.joinpath(self.filename) for d in dirs]: + if not path.exists(): + log.info(f"Not found: {path}") + continue + if "test" in path.parts: + log.warning(f"Reading random data from {path}") + break - return iamc_like_data_for_query(path, query, replace=self.replace) + self.path = path + + def __call__(self): + # Use prepared path, query, and replacements + return iamc_like_data_for_query(self.path, self.query, replace=self.replace) @register_source @@ -123,6 +122,7 @@ class SSPUpdate(ExoDataSource): - `source`: Any value from :data:`.SSP_2024` or equivalent string, for instance "ICONICS:SSP(2024).2". + - `release`: One of "3.0" or "preview". Example ------- @@ -137,28 +137,32 @@ class SSPUpdate(ExoDataSource): id = "SSP update" + #: File names containing the data, according to the release. + filename = { + "3.0": "1706548837040-ssp_basic_drivers_release_3.0_full.csv.gz", + "preview": "SSP-Review-Phase-1.csv.gz", + } + def __init__(self, source, source_kw): s = "ICONICS:SSP(2024)." if not source.startswith(s): raise ValueError(source) - *parts, self.ssp_number = source.partition(s) + *parts, ssp_id = source.partition(s) - # Map the `measure` keyword to a string appearing in the data - _kw = copy(source_kw) + # Map the `measure` keyword to a 'Variable' dimension code measure = { "GDP": "GDP|PPP", "POP": "Population", - }[_kw.pop("measure")] + }[source_kw.pop("measure")] - # Store the model ID, if any - self.model = _kw.pop("model", None) + # Store the model code, if any + model = source_kw.pop("model", None) # Identify the data release date/version/label - self.release = _kw.pop("release", "3.0") + release = source_kw.pop("release", "3.0") - # Directories in which to locate `self.filename` - self.dirs = [] + self.raise_on_extra_kw(source_kw) # Replacements to apply, if any self.replace = {} @@ -167,29 +171,33 @@ def __init__(self, source, source_kw): models = [] scenarios = [] - if self.release == "3.0": - self.filename = "1706548837040-ssp_basic_drivers_release_3.0_full.csv.gz" - # Stored directly in message_ix_models - self.dirs.append(package_data_path("ssp")) - scenarios.append(f"SSP{self.ssp_number}") + if release == "3.0": + # Directories in which to locate `self.filename`; stored directly within + # message_ix_models + dirs = [package_data_path("ssp")] - if measure == "GDP|PPP" and self.model != "OECD ENV-Growth 2023": - # Configure to prepend s="Historical Reference" observations to series - models.extend([self.model, "OECD ENV-Growth 2023"]) + scenarios.append(f"SSP{ssp_id}") + + if measure == "GDP|PPP": + # Configure to prepend (m="OECD…", s="Historical Reference") + # observations to series + models.extend({model, "OECD ENV-Growth 2023"}) scenarios.append("Historical Reference") self.replace.update( - Model={"OECD ENV-Growth 2023": models[0]}, + Model={"OECD ENV-Growth 2023": model}, Scenario={"Historical Reference": scenarios[0]}, ) - elif self.release == "preview": - self.filename = "SSP-Review-Phase-1.csv.gz" + elif release == "preview": # Look first in message_data, then in message_ix_models test data - self.dirs.extend( - [private_data_path("ssp"), package_data_path("test", "ssp")] - ) - scenarios.append(f"SSP{self.ssp_number} - Review Phase 1") + dirs = [private_data_path("ssp"), package_data_path("test", "ssp")] + + scenarios.append(f"SSP{ssp_id} - Review Phase 1") else: - raise ValueError(f"{self.release = }") + log.error( + f"{release = } invalid for {type(self)}; expected one of: " + f"{set(self.filename)}" + ) + raise ValueError(release) # Assemble and store a query string self.query = f"Scenario in {scenarios!r} and Variable == '{measure}'" + ( @@ -197,19 +205,17 @@ def __init__(self, source, source_kw): ) # log.info(f"{self.query = }") - if len(_kw): - raise ValueError(_kw) - - def __call__(self): - # Iterate over possible locations for self.filename - for dir in self.dirs: - path = dir.joinpath(self.filename) + # Iterate over possible locations for the data file + for path in [d.joinpath(self.filename[release]) for d in dirs]: if not path.exists(): log.info(f"Not found: {path}") - elif "test" in path.parts: + continue + if "test" in path.parts: log.warning(f"Reading random data from {path}") - else: - break + break - # Use prepared query and replacements - return iamc_like_data_for_query(path, self.query, replace=self.replace) + self.path = path + + def __call__(self): + # Use prepared path, query, and replacements + return iamc_like_data_for_query(self.path, self.query, replace=self.replace) From d16052f0e7b8c55ee05500245a23b64f9abb3276 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 11:06:06 +0100 Subject: [PATCH 23/54] Don't generate log files while testing Improve CLI help texts. --- message_ix_models/cli.py | 3 ++- message_ix_models/project/ssp/__init__.py | 2 +- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/message_ix_models/cli.py b/message_ix_models/cli.py index 31d52825e8..c13cc0a0ce 100644 --- a/message_ix_models/cli.py +++ b/message_ix_models/cli.py @@ -11,7 +11,7 @@ The top-level options --platform, --model, and --scenario are used by commands that access specific message_ix scenarios; these can also be specified with --url. -For more information, see https://docs.messageix.org/projects/models2/en/latest/cli.html +For more information, see https://docs.messageix.org/projects/models/en/latest/cli.html """ import logging @@ -57,6 +57,7 @@ def main(click_ctx, **kwargs): non_trivial = ( not any(s in sys.argv for s in {"last-log", "--help"}) and click_ctx.invoked_subcommand != "_test" + and "pytest" not in sys.argv[0] ) # Log to console: either DEBUG or INFO. diff --git a/message_ix_models/project/ssp/__init__.py b/message_ix_models/project/ssp/__init__.py index 5aed2aee31..4c30d43a14 100644 --- a/message_ix_models/project/ssp/__init__.py +++ b/message_ix_models/project/ssp/__init__.py @@ -59,7 +59,7 @@ def __set__(self, obj, value): @click.group("ssp") def cli(): - pass + """Shared Socioeconomic Pathways (SSP) project.""" @cli.command("gen-structures") From 2bcd79419a18c22f63f129576dad8496a2bb29c6 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 11:27:05 +0100 Subject: [PATCH 24/54] Add Context.__eq__() Avoid comparing entire contents of Context for .index(). --- message_ix_models/util/context.py | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/message_ix_models/util/context.py b/message_ix_models/util/context.py index 0182701ef8..b5c2b3e84d 100644 --- a/message_ix_models/util/context.py +++ b/message_ix_models/util/context.py @@ -139,6 +139,12 @@ def __deepcopy__(self, memo): return result + def __eq__(self, other) -> bool: + # Don't compare contents, only identity, for _CONTEXTS.index() + if not isinstance(other, Context): + return NotImplemented + return id(self) == id(other) + def __repr__(self): return f"<{self.__class__.__name__} object at {id(self)} with {len(self)} keys>" From 911d296df0eb41b67d6d74e02411b8ae0170af3a Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 11:39:41 +0100 Subject: [PATCH 25/54] Fall back to local data in private_data_path() --- message_ix_models/util/common.py | 19 +++++++++++++++---- 1 file changed, 15 insertions(+), 4 deletions(-) diff --git a/message_ix_models/util/common.py b/message_ix_models/util/common.py index 5d75c7760d..6df24ae757 100644 --- a/message_ix_models/util/common.py +++ b/message_ix_models/util/common.py @@ -258,11 +258,15 @@ def package_data_path(*parts) -> Path: return _make_path(MESSAGE_MODELS_PATH / "data", *parts) -def private_data_path(*parts) -> Path: # pragma: no cover (needs message_data) +def private_data_path(*parts) -> Path: """Construct a path to a file under :file:`data/` in :mod:`message_data`. - Use this function to access non-public (e.g. embargoed or proprietary) data stored - in the :mod:`message_data` repository. + Use this function to access non-public (for instance, embargoed or proprietary) data + stored in the :mod:`message_data` repository. + + If the repository is not available, the function falls back to + :meth:`.Context.get_local_path`, where users may put files obtained through other + messages. Parameters ---------- @@ -273,4 +277,11 @@ def private_data_path(*parts) -> Path: # pragma: no cover (needs message_data) -------- :ref:`Choose locations for data ` """ - return _make_path(cast(Path, MESSAGE_DATA_PATH) / "data", *parts) + if HAS_MESSAGE_DATA: + return _make_path(cast(Path, MESSAGE_DATA_PATH) / "data", *parts) + else: + from .context import Context + + base = Context.get_instance(-1).get_local_path() + log.warning(f"message_data not installed; fall back to {base}") + return base.joinpath(*parts) From 56ebe7c4e4adf6791696bfe26f40ba1c3863ed84 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 11:42:04 +0100 Subject: [PATCH 26/54] Apply `ruff format .` to 21 files (whitespace only) --- message_ix_models/model/__init__.py | 1 + message_ix_models/model/macro.py | 1 + message_ix_models/model/snapshot.py | 1 + .../model/water/data/pre_processing/hydro_agg_raster.py | 1 + message_ix_models/project/ssp/structure.py | 1 + message_ix_models/report/compat.py | 1 + message_ix_models/report/operator.py | 1 + message_ix_models/report/plot.py | 1 + message_ix_models/report/sim.py | 1 + message_ix_models/tests/model/test_disutility.py | 1 + message_ix_models/tests/test_cli.py | 1 + message_ix_models/tests/test_util.py | 1 + message_ix_models/tests/util/test_click.py | 1 + message_ix_models/tests/util/test_node.py | 1 + message_ix_models/tools/advance.py | 1 + message_ix_models/tools/iamc.py | 1 + message_ix_models/tools/iea/web.py | 1 + message_ix_models/tools/wb.py | 1 + message_ix_models/util/click.py | 1 + message_ix_models/util/node.py | 1 + message_ix_models/util/pooch.py | 1 + 21 files changed, 21 insertions(+) diff --git a/message_ix_models/model/__init__.py b/message_ix_models/model/__init__.py index a96809062c..08625fb96b 100644 --- a/message_ix_models/model/__init__.py +++ b/message_ix_models/model/__init__.py @@ -1,4 +1,5 @@ """Code for constructing models/scenarios in the MESSAGEix-GLOBIOM model family.""" + from .config import Config __all__ = ["Config"] diff --git a/message_ix_models/model/macro.py b/message_ix_models/model/macro.py index 57419a9610..37ac1177f9 100644 --- a/message_ix_models/model/macro.py +++ b/message_ix_models/model/macro.py @@ -3,6 +3,7 @@ See :doc:`message-ix:macro` for *general* documentation on MACRO and MESSAGE-MACRO. This module contains tools specifically for using these models with MESSAGEix-GLOBIOM. """ + import logging from functools import lru_cache from itertools import product diff --git a/message_ix_models/model/snapshot.py b/message_ix_models/model/snapshot.py index f1afb820bd..60600c4cb9 100644 --- a/message_ix_models/model/snapshot.py +++ b/message_ix_models/model/snapshot.py @@ -1,4 +1,5 @@ """Prepare base models from snapshot data.""" + import logging from pathlib import Path diff --git a/message_ix_models/model/water/data/pre_processing/hydro_agg_raster.py b/message_ix_models/model/water/data/pre_processing/hydro_agg_raster.py index b7c3dd8632..0c9d582cd9 100644 --- a/message_ix_models/model/water/data/pre_processing/hydro_agg_raster.py +++ b/message_ix_models/model/water/data/pre_processing/hydro_agg_raster.py @@ -5,6 +5,7 @@ data onto the basin mapping used in the nexus module. """ + import glob # Import packages diff --git a/message_ix_models/project/ssp/structure.py b/message_ix_models/project/ssp/structure.py index ba8e9ab8aa..0119f3f410 100644 --- a/message_ix_models/project/ssp/structure.py +++ b/message_ix_models/project/ssp/structure.py @@ -1,4 +1,5 @@ """Manipulate data structures for working with the SSPs.""" + import logging from textwrap import wrap from typing import TYPE_CHECKING, Optional diff --git a/message_ix_models/report/compat.py b/message_ix_models/report/compat.py index c032a59338..84f63d48e8 100644 --- a/message_ix_models/report/compat.py +++ b/message_ix_models/report/compat.py @@ -1,4 +1,5 @@ """Compatibility code that emulates :mod:`.message_data` reporting.""" + import logging from functools import partial from itertools import chain, count diff --git a/message_ix_models/report/operator.py b/message_ix_models/report/operator.py index 2de6390d37..65f993bad1 100644 --- a/message_ix_models/report/operator.py +++ b/message_ix_models/report/operator.py @@ -1,4 +1,5 @@ """Atomic reporting operations for MESSAGEix-GLOBIOM.""" + import itertools import logging import re diff --git a/message_ix_models/report/plot.py b/message_ix_models/report/plot.py index c282431862..500f9197d8 100644 --- a/message_ix_models/report/plot.py +++ b/message_ix_models/report/plot.py @@ -3,6 +3,7 @@ The current set functions on time series data stored on the scenario by :mod:`message_ix_models.report` or :mod:`message_data` legacy reporting. """ + import logging import re from datetime import datetime diff --git a/message_ix_models/report/sim.py b/message_ix_models/report/sim.py index 9ad6a76a03..bf18c4b375 100644 --- a/message_ix_models/report/sim.py +++ b/message_ix_models/report/sim.py @@ -1,4 +1,5 @@ """Simulated solution data for testing :mod:`~message_ix_models.report`.""" + import logging from collections import ChainMap, defaultdict from collections.abc import Mapping diff --git a/message_ix_models/tests/model/test_disutility.py b/message_ix_models/tests/model/test_disutility.py index f78342f86b..83aaa41fe0 100644 --- a/message_ix_models/tests/model/test_disutility.py +++ b/message_ix_models/tests/model/test_disutility.py @@ -1,4 +1,5 @@ """Tests of :mod:`.model.disutility`.""" + from itertools import product import pandas as pd diff --git a/message_ix_models/tests/test_cli.py b/message_ix_models/tests/test_cli.py index a1b7118a30..5b4f6b2313 100644 --- a/message_ix_models/tests/test_cli.py +++ b/message_ix_models/tests/test_cli.py @@ -1,4 +1,5 @@ """Basic tests of the command line.""" + import ixmp import pytest from message_ix.testing import make_dantzig diff --git a/message_ix_models/tests/test_util.py b/message_ix_models/tests/test_util.py index ee1fa00ae6..cf0d43bd59 100644 --- a/message_ix_models/tests/test_util.py +++ b/message_ix_models/tests/test_util.py @@ -1,4 +1,5 @@ """Tests of :mod:`message_ix_models.util`.""" + import logging import re from importlib.metadata import version diff --git a/message_ix_models/tests/util/test_click.py b/message_ix_models/tests/util/test_click.py index fe0f26ac71..f4f0be55bb 100644 --- a/message_ix_models/tests/util/test_click.py +++ b/message_ix_models/tests/util/test_click.py @@ -1,4 +1,5 @@ """Basic tests of the command line.""" + import click from message_ix_models.util.click import common_params diff --git a/message_ix_models/tests/util/test_node.py b/message_ix_models/tests/util/test_node.py index 8cfaafef4b..3365708fe4 100644 --- a/message_ix_models/tests/util/test_node.py +++ b/message_ix_models/tests/util/test_node.py @@ -1,4 +1,5 @@ """Tests of :mod:`message_ix_models.util.node`.""" + import re import pandas as pd diff --git a/message_ix_models/tools/advance.py b/message_ix_models/tools/advance.py index d8558d5905..fff6a5e511 100644 --- a/message_ix_models/tools/advance.py +++ b/message_ix_models/tools/advance.py @@ -1,4 +1,5 @@ """Handle data from the ADVANCE project.""" + import logging from pathlib import Path from typing import Optional diff --git a/message_ix_models/tools/iamc.py b/message_ix_models/tools/iamc.py index 66d3c3e0fd..91f5e9fbcd 100644 --- a/message_ix_models/tools/iamc.py +++ b/message_ix_models/tools/iamc.py @@ -1,4 +1,5 @@ """Tools for working with IAMC-structured data.""" + from typing import Optional import pandas as pd diff --git a/message_ix_models/tools/iea/web.py b/message_ix_models/tools/iea/web.py index 659824db81..e78a288ac8 100644 --- a/message_ix_models/tools/iea/web.py +++ b/message_ix_models/tools/iea/web.py @@ -1,4 +1,5 @@ """Tools for IEA (Extended) World Energy Balance (WEB) data.""" + import logging import zipfile from copy import copy diff --git a/message_ix_models/tools/wb.py b/message_ix_models/tools/wb.py index 430922129d..16e3d8e009 100644 --- a/message_ix_models/tools/wb.py +++ b/message_ix_models/tools/wb.py @@ -1,4 +1,5 @@ """Tools for World Bank data.""" + import logging from collections import defaultdict from functools import lru_cache diff --git a/message_ix_models/util/click.py b/message_ix_models/util/click.py index fae8891093..5760fd34f9 100644 --- a/message_ix_models/util/click.py +++ b/message_ix_models/util/click.py @@ -2,6 +2,7 @@ These are used for building CLIs using :mod:`click`. """ + import logging from datetime import datetime from pathlib import Path diff --git a/message_ix_models/util/node.py b/message_ix_models/util/node.py index 6d7206e6b8..2446acb569 100644 --- a/message_ix_models/util/node.py +++ b/message_ix_models/util/node.py @@ -1,4 +1,5 @@ """Utilities for nodes.""" + import logging from typing import List, Sequence, Union diff --git a/message_ix_models/util/pooch.py b/message_ix_models/util/pooch.py index 1540ecdf99..4f12205c66 100644 --- a/message_ix_models/util/pooch.py +++ b/message_ix_models/util/pooch.py @@ -1,4 +1,5 @@ """Utilities for using :doc:`Pooch `.""" + import logging from pathlib import Path from typing import Tuple From 704c0a36d1f75781288be271df4ea11e5feafbb6 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 11:42:32 +0100 Subject: [PATCH 27/54] Apply `ruff format .` to 2 files in .water.data --- message_ix_models/model/water/data/infrastructure.py | 2 +- .../water/data/pre_processing/hydro_agg_basin.py | 12 ++++++------ 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/message_ix_models/model/water/data/infrastructure.py b/message_ix_models/model/water/data/infrastructure.py index 92d1c801f0..9e5b894b45 100644 --- a/message_ix_models/model/water/data/infrastructure.py +++ b/message_ix_models/model/water/data/infrastructure.py @@ -1,5 +1,5 @@ """Prepare data for adding techs related to water distribution, - treatment in urban & rural""" +treatment in urban & rural""" from collections import defaultdict diff --git a/message_ix_models/model/water/data/pre_processing/hydro_agg_basin.py b/message_ix_models/model/water/data/pre_processing/hydro_agg_basin.py index 6e19eb0044..5a3e245510 100644 --- a/message_ix_models/model/water/data/pre_processing/hydro_agg_basin.py +++ b/message_ix_models/model/water/data/pre_processing/hydro_agg_basin.py @@ -156,9 +156,9 @@ def bias_correction(df): final_temp = pd.concat((final_temp, temp), axis=1) df_monthly = final_temp - df[ - pd.date_range(str(year) + "-01-01", periods=12, freq="M") - ] = final_temp.groupby(final_temp.columns.month, axis=1).mean() + df[pd.date_range(str(year) + "-01-01", periods=12, freq="M")] = ( + final_temp.groupby(final_temp.columns.month, axis=1).mean() + ) # 5 year monthly data df_5y_m = df[df.columns[df.columns.year.isin(years)]] # 5 year annual @@ -319,9 +319,9 @@ def bias_correction(df): ] df_monthly = final_temp - eflow[ - pd.date_range(str(year) + "-01-01", periods=12, freq="M") - ] = final_temp.groupby(final_temp.columns.month, axis=1).mean() + eflow[pd.date_range(str(year) + "-01-01", periods=12, freq="M")] = ( + final_temp.groupby(final_temp.columns.month, axis=1).mean() + ) eflow_5y_m = eflow[eflow.columns[eflow.columns.year.isin(years)]] eflow_5y_m.to_csv(wd11 + f"e-flow_5y_m_7p0_{iso3}.csv") From 0f769179908a82037768c69dab49dd76830f5d19 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 11:43:51 +0100 Subject: [PATCH 28/54] Bump ruff, mypy versions in pre-commit config MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Ruff v0.3.0 → v0.3.2 Mypy v1.8.0 → v1.9.0 --- .pre-commit-config.yaml | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index 2d531248e9..8c5cf505ab 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -10,7 +10,7 @@ repos: language: python entry: bash -c ". ${PRE_COMMIT_MYPY_VENV:-/dev/null}/bin/activate 2>/dev/null; mypy $0 $@; python -m pip list" additional_dependencies: - - mypy >= 1.8.0 + - mypy >= 1.9.0 - plotnine - pytest - sdmx1 @@ -20,7 +20,7 @@ repos: - "message-ix @ git+https://github.com/iiasa/message_ix.git@main" args: ["."] - repo: https://github.com/astral-sh/ruff-pre-commit - rev: v0.3.0 + rev: v0.3.2 hooks: - id: ruff - id: ruff-format From d8f287f14e5254207fcb6ae76df22ae75eefb91e Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 11:48:30 +0100 Subject: [PATCH 29/54] =?UTF-8?q?Adjust=20max-complexity=2013=20=E2=86=92?= =?UTF-8?q?=2011?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Mark two exceptions - Move ruff config in pyproject.toml to current (non-deprecated) locations. --- message_ix_models/tools/wb.py | 3 ++- message_ix_models/util/sdmx.py | 5 ++++- pyproject.toml | 9 +++++---- 3 files changed, 11 insertions(+), 6 deletions(-) diff --git a/message_ix_models/tools/wb.py b/message_ix_models/tools/wb.py index 16e3d8e009..08525c15d5 100644 --- a/message_ix_models/tools/wb.py +++ b/message_ix_models/tools/wb.py @@ -13,7 +13,8 @@ log = logging.getLogger(__name__) -def assign_income_groups( +# FIXME Reduce complexity from 12 → ≤11 +def assign_income_groups( # noqa: C901 cl_node: "sdmx.model.common.Codelist", cl_income_group: "sdmx.model.common.Codelist", method: str = "population", diff --git a/message_ix_models/util/sdmx.py b/message_ix_models/util/sdmx.py index e17b14b26d..1e7176826f 100644 --- a/message_ix_models/util/sdmx.py +++ b/message_ix_models/util/sdmx.py @@ -25,7 +25,10 @@ CodeLike = Union[str, Code] -def as_codes(data: Union[List[str], Dict[str, CodeLike]]) -> List[Code]: +# FIXME Reduce complexity from 13 → ≤11 +def as_codes( # noqa: C901 + data: Union[List[str], Dict[str, CodeLike]], +) -> List[Code]: """Convert `data` to a :class:`list` of |Code| objects. Various inputs are accepted: diff --git a/pyproject.toml b/pyproject.toml index a2cd936fda..ec8f9a2ca8 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -117,11 +117,12 @@ no_implicit_optional = false addopts = "-p no:faulthandler --cov=message_ix_models --cov-report=" filterwarnings = "ignore:distutils Version classes.*:DeprecationWarning" -[tool.ruff] +[tool.ruff.lint] select = ["C9", "E", "F", "I", "W"] - -[tool.ruff.mccabe] -max-complexity = 13 +# Exceptions: +# - .tools.wb.assign_income_groups(): 12 > 11 +# - .util.sdmx.as_codes(): 13 > 11 +mccabe.max-complexity = 11 [tool.setuptools.packages] find = {} From 856824b38bbdcd92e8657824d6f8dc64d06eee3c Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 12:15:45 +0100 Subject: [PATCH 30/54] Supply globals in test_process_units_anno() --- message_ix_models/tests/model/test_structure.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/message_ix_models/tests/model/test_structure.py b/message_ix_models/tests/model/test_structure.py index e9724d05b8..dcc0ce2f21 100644 --- a/message_ix_models/tests/model/test_structure.py +++ b/message_ix_models/tests/model/test_structure.py @@ -278,4 +278,6 @@ def test_process_units_anno(): process_units_anno("", codes[0]) # Parents' units are propagated to the child - assert registry.Unit("kg") == codes[1].eval_annotation("units") + assert registry.Unit("kg") == codes[1].eval_annotation( + "units", dict(registry=registry) + ) From 9661f3b080b881802f7cc717148ebc0ee3302fc8 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Tue, 12 Mar 2024 12:54:40 +0100 Subject: [PATCH 31/54] Adjust QueueHandler for Python 3.12 compatibility --- message_ix_models/util/_logging.py | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/message_ix_models/util/_logging.py b/message_ix_models/util/_logging.py index b33211635e..4302184468 100644 --- a/message_ix_models/util/_logging.py +++ b/message_ix_models/util/_logging.py @@ -131,16 +131,21 @@ def format(self, record): class QueueHandler(logging.handlers.QueueHandler): """Queue handler with custom set-up. - This emulates the default behaviour available in Python 3.12. + This emulates the default behaviour available in Python 3.12 for Python 3.11 and + earlier; it is also compatible with Python 3.12. """ #: Corresponding listener that dispatches to the actual handlers. listener: logging.handlers.QueueListener def __init__( - self, *, handlers: List[str] = [], respect_handler_level: bool = False + self, + queue=None, # For Python 3.12 + *, + handlers: List[str] = [], # For Python 3.11 and earlier + respect_handler_level: bool = False, ) -> None: - super().__init__(SimpleQueue()) + super().__init__(queue or SimpleQueue()) # Construct the listener # NB This relies on the non-public collection logging._handlers From b627bb461e0b05e6d6a0851a9e2ad9e5abaf31db Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Thu, 14 Mar 2024 13:30:47 +0100 Subject: [PATCH 32/54] Add dependabot configuration for GitHub Actions --- .github/dependabot.yml | 27 +++++++++++++++++++++++++++ 1 file changed, 27 insertions(+) create mode 100644 .github/dependabot.yml diff --git a/.github/dependabot.yml b/.github/dependabot.yml new file mode 100644 index 0000000000..61a3dd3975 --- /dev/null +++ b/.github/dependabot.yml @@ -0,0 +1,27 @@ +version: 2 +updates: + - package-ecosystem: "github-actions" + # Only update major versions + ignore: + - dependency-name: "*" + update-types: + - "version-update:semver-minor" + - "version-update:semver-patch" + # Below config mirrors the example at + # https://github.com/dependabot/dependabot-core/blob/main/.github/dependabot.yml + directory: "/" + schedule: + interval: "weekly" + day: "sunday" + time: "16:00" + groups: + all-actions: + patterns: [ "*" ] + assignees: + - "glatterf42" + - "khaeru" + labels: + - "dependencies" + reviewers: + - "glatterf42" + - "khaeru" From d16d829235a965d00296c9a636e3851ffdd8dc70 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Thu, 14 Mar 2024 15:56:39 +0100 Subject: [PATCH 33/54] Improve check for QueueHandler in _logging.setup() Don't depend on the instance being the first or only handler. --- message_ix_models/util/_logging.py | 62 +++++++++++++++--------------- 1 file changed, 30 insertions(+), 32 deletions(-) diff --git a/message_ix_models/util/_logging.py b/message_ix_models/util/_logging.py index 4302184468..6b37de8527 100644 --- a/message_ix_models/util/_logging.py +++ b/message_ix_models/util/_logging.py @@ -7,10 +7,11 @@ import sys import time from contextlib import contextmanager +from copy import deepcopy from datetime import datetime, timedelta, timezone from queue import SimpleQueue from time import process_time -from typing import List, Union +from typing import List, Union, cast # NB mark_time, preserve_log_level, and silence_log are exposed by util/__init__.py __all__ = [ @@ -43,7 +44,6 @@ }, ) - _CONFIG = dict( version=1, disable_existing_loggers=False, @@ -180,18 +180,6 @@ def stream(self): return getattr(sys, self.stream_name) -def _get_handler(name: str) -> logging.Handler: - """Retrieve one of the handlers of the :class:`logging.handlers.QueueListener`.""" - queue_handler = logging.getLogger().handlers[0] - assert isinstance(queue_handler, QueueHandler) - - for h in queue_handler.listener.handlers: - if h.name == name: - return h - - raise ValueError(name) - - def mark_time(quiet: bool = False) -> None: """Record and log (if `quiet` is :obj:`True`) a time mark.""" _TIMES.append(process_time()) @@ -235,32 +223,42 @@ def setup( """ from platformdirs import user_log_path - # Construct the file name for the log file - filename = ( - datetime.now(timezone(timedelta(seconds=time.timezone))) - .isoformat(timespec="seconds") - .replace(":", "") - ) - log_dir = user_log_path("message-ix-models", ensure_exists=True) - _HANDLER_CONFIG["file"].setdefault("filename", log_dir.joinpath(filename)) - _CONFIG["handlers"] = _HANDLER_CONFIG - root = logging.getLogger() - if not root.handlers: - # Not yet configured → apply the configuration - logging.config.dictConfig(_CONFIG) + if not any(isinstance(h, QueueHandler) for h in root.handlers): + # Not yet configured + + # Construct the file name for the log file + log_file_path = user_log_path("message-ix-models", ensure_exists=True).joinpath( + datetime.now(timezone(timedelta(seconds=time.timezone))) + .isoformat(timespec="seconds") + .replace(":", "") + ) + + # Copy and modify dictionaries + config_handlers = deepcopy(_HANDLER_CONFIG) + config_handlers["file"].update(filename=log_file_path) + config = deepcopy(_CONFIG) + config.update(handlers=config_handlers) + + # Apply the configuration + logging.config.dictConfig(config) # Apply settings to loggers and handlers: either just-created, or pre-existing + # Identify the QueueHandler instance + queue_handler = next(filter(lambda qh: isinstance(qh, QueueHandler), root.handlers)) + assert isinstance(queue_handler, QueueHandler) + # Prepare a dictionary of the listener's handlers + handler = {h.name: h for h in queue_handler.listener.handlers} + # Set the level of the console handler - _get_handler("console").setLevel(99 if console is False else level) + handler["console"].setLevel(99 if console is False else level) - file_handler = _get_handler("file") if file is False: - file_handler.setLevel(99) + handler["file"].setLevel(99) else: - file_handler.setLevel("DEBUG") - log.info(f"Log to {_HANDLER_CONFIG['file']['filename']!s}") + handler["file"].setLevel("DEBUG") + log.info(f"Log to {cast(logging.FileHandler, handler['file']).baseFilename}") @contextmanager From e0d5c3a4aa30cd6f6548b99128aa21fa3ec6bc5d Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Thu, 14 Mar 2024 20:13:34 +0100 Subject: [PATCH 34/54] Test QueueListener on multiple processes/threads --- message_ix_models/tests/util/test_logging.py | 37 ++++++++++++++++++++ 1 file changed, 37 insertions(+) diff --git a/message_ix_models/tests/util/test_logging.py b/message_ix_models/tests/util/test_logging.py index f3be6907de..5a21f90bfd 100644 --- a/message_ix_models/tests/util/test_logging.py +++ b/message_ix_models/tests/util/test_logging.py @@ -1,6 +1,9 @@ import logging import re +import click +import pytest + from message_ix_models.util._logging import mark_time, silence_log @@ -17,6 +20,40 @@ def test_mark_time(caplog): assert all(re.match(r" \+\d+\.\d = \d+\.\d seconds", m) for m in caplog.messages) +class TestQueueListener: + #: Number of log messages to emit. + N = 1_000 + + #: Number of times to run the test. + k = 4 + + @pytest.mark.parametrize("k", range(k)) + def test_flush(self, caplog, mix_models_cli, k): + """Test logging in multiple processes, multiple threads, and with :mod:`click`. + + With pytest-xdist, these :attr:`k` test cases will run in multiple processes. + Each process will have its main thread, and the thread of the QueueListener. + The test ensures that all :attr:`N` log records emitted by the :py:`func()` are + "flushed" from the queue, transferred to stdout by the :class:`.StreamHandler` + and captured by the :class:`.CliRunner`. + """ + + @click.command("log-threads") + def func(): + # Emit many log records + log = logging.getLogger("message_ix_models") + [log.info(f"{k = } {i = }") for i in range(self.N)] + + with mix_models_cli.temporary_command(func): + # Run the command, capture output + result = mix_models_cli.assert_exit_0(["_test", func.name]) + + # All records are emitted; the last record ends with N - 1 + assert result.output.rstrip().endswith(f"{self.N - 1}"), result.output.split( + "\n" + )[-2:] + + def test_silence_log(caplog): # An example logger log = logging.getLogger("message_ix_models.model") From 4a74d2b9b6eda91a394e46293e5b40d1c4bd04b2 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Thu, 14 Mar 2024 20:17:04 +0100 Subject: [PATCH 35/54] Subclass QueueListener to add .flush() --- message_ix_models/util/_logging.py | 39 +++++++++++++++++++++++------- 1 file changed, 30 insertions(+), 9 deletions(-) diff --git a/message_ix_models/util/_logging.py b/message_ix_models/util/_logging.py index 6b37de8527..ba0b63fed0 100644 --- a/message_ix_models/util/_logging.py +++ b/message_ix_models/util/_logging.py @@ -11,7 +11,7 @@ from datetime import datetime, timedelta, timezone from queue import SimpleQueue from time import process_time -from typing import List, Union, cast +from typing import Dict, List, Union, cast # NB mark_time, preserve_log_level, and silence_log are exposed by util/__init__.py __all__ = [ @@ -23,6 +23,8 @@ log = logging.getLogger(__name__) +_HANDLER: Dict[str, logging.Handler] = dict() + # NB This is only separate to avoid complaints from mypy _HANDLER_CONFIG = dict( console={ @@ -136,7 +138,7 @@ class QueueHandler(logging.handlers.QueueHandler): """ #: Corresponding listener that dispatches to the actual handlers. - listener: logging.handlers.QueueListener + listener: "QueueListener" def __init__( self, @@ -149,16 +151,25 @@ def __init__( # Construct the listener # NB This relies on the non-public collection logging._handlers - self.listener = logging.handlers.QueueListener( + self.listener = QueueListener( self.queue, *[logging._handlers[name] for name in handlers], # type: ignore [attr-defined] respect_handler_level=respect_handler_level, ) - self.listener.start() atexit.register(self.listener.stop) +class QueueListener(logging.handlers.QueueListener): + """:class:`.logging.QueueListener` with a :meth:`.flush` method.""" + + def flush(self): + """Flush the queue: join the listener/monitor thread and then restart.""" + if self._thread is not None: + super().stop() + self.start() + + class StreamHandler(logging.StreamHandler): """Like :class:`.logging.StreamHandler`, but refresh sys.stdout on each access. @@ -204,6 +215,9 @@ def preserve_log_level(): main_log.setLevel(level) +_HANDLER = dict() + + def setup( level: Union[str, int] = 99, console: bool = True, @@ -248,17 +262,24 @@ def setup( # Identify the QueueHandler instance queue_handler = next(filter(lambda qh: isinstance(qh, QueueHandler), root.handlers)) assert isinstance(queue_handler, QueueHandler) + _HANDLER.update(queue=queue_handler) + # Prepare a dictionary of the listener's handlers - handler = {h.name: h for h in queue_handler.listener.handlers} + _HANDLER.update({str(h.name): h for h in queue_handler.listener.handlers}) # Set the level of the console handler - handler["console"].setLevel(99 if console is False else level) + _HANDLER["console"].setLevel(99 if console is False else level) if file is False: - handler["file"].setLevel(99) + _HANDLER["file"].setLevel(99) else: - handler["file"].setLevel("DEBUG") - log.info(f"Log to {cast(logging.FileHandler, handler['file']).baseFilename}") + _HANDLER["file"].setLevel("DEBUG") + log.info(f"Log to {cast(logging.FileHandler, _HANDLER['file']).baseFilename}") + + +def flush() -> None: + """Flush the queue.""" + cast(QueueHandler, _HANDLER["queue"]).listener.flush() @contextmanager From a066a89e760d60642a84114a3a0a9b3fd81cc006 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Thu, 14 Mar 2024 20:18:27 +0100 Subject: [PATCH 36/54] Flush logging queue on CLI exit --- message_ix_models/cli.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/message_ix_models/cli.py b/message_ix_models/cli.py index c13cc0a0ce..03fce1d605 100644 --- a/message_ix_models/cli.py +++ b/message_ix_models/cli.py @@ -21,7 +21,7 @@ import click from ixmp.cli import main as ixmp_cli -from message_ix_models.util._logging import mark_time +from message_ix_models.util._logging import flush, mark_time from message_ix_models.util._logging import setup as setup_logging from message_ix_models.util.click import common_params from message_ix_models.util.context import Context @@ -80,6 +80,9 @@ def main(click_ctx, **kwargs): # Close any database connections when the CLI exits click_ctx.call_on_close(click_ctx.obj.close_db) + # Ensure all log messages are handled + click_ctx.call_on_close(flush) + @main.command("export-test-data") @click.option("--exclude", default="", help="Sheets to exclude.") From f13622a41f075bef9237d3d0d0f4573bc220c92e Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Thu, 14 Mar 2024 20:51:58 +0100 Subject: [PATCH 37/54] Quiet warning about missing message_data (closes #37) --- message_ix_models/cli.py | 22 +++++++++++++++++----- message_ix_models/util/common.py | 1 - message_ix_models/util/config.py | 1 + 3 files changed, 18 insertions(+), 6 deletions(-) diff --git a/message_ix_models/cli.py b/message_ix_models/cli.py index 03fce1d605..db818ca7f7 100644 --- a/message_ix_models/cli.py +++ b/message_ix_models/cli.py @@ -149,11 +149,23 @@ def debug(ctx): import message_data.cli except ImportError: # message_data is not installed or contains some ImportError of its own - from traceback import format_exception - - # Display information for debugging - etype, value, tb = sys.exc_info() - print("", *format_exception(etype, value, tb, limit=-1, chain=False)[1:], sep="\n") + import ixmp + + if ixmp.config.get("no message_data") is not True: + print( + "Warning: message_data is not installed or cannot be imported; see the " + "documentation via --help" + ) + + # commented: Display verbose information for debugging + # from traceback import format_exception + # + # etype, value, tb = sys.exc_info() + # print( + # "", + # *format_exception(etype, value, tb, limit=-1, chain=False)[1:], + # sep="\n", + # ) else: # pragma: no cover (needs message_data) # Also add message_data submodules submodules.extend( diff --git a/message_ix_models/util/common.py b/message_ix_models/util/common.py index 6df24ae757..3c2a12bf31 100644 --- a/message_ix_models/util/common.py +++ b/message_ix_models/util/common.py @@ -12,7 +12,6 @@ try: import message_data except ImportError: - log.warning("message_data is not installed or cannot be imported") MESSAGE_DATA_PATH: Optional[Path] = None HAS_MESSAGE_DATA = False else: # pragma: no cover (needs message_data) diff --git a/message_ix_models/util/config.py b/message_ix_models/util/config.py index c25d1a42c6..d6bf3299df 100644 --- a/message_ix_models/util/config.py +++ b/message_ix_models/util/config.py @@ -10,6 +10,7 @@ log = logging.getLogger(__name__) +ixmp.config.register("no message_data", bool, False) ixmp.config.register("message local data", Path, Path.cwd()) From e3dc0af1dd13f7c618887ad2d2c2744ee8d6723c Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Thu, 14 Mar 2024 20:53:24 +0100 Subject: [PATCH 38/54] Expand and improve CLI docs - Document "no_message_data" config setting. - Use :program: Sphinx role throughout. - Don't use a private command as an example in --help. - Refresh --help output text shown in docs. --- doc/cli.rst | 112 +++++++++++++++++++++++---------------- message_ix_models/cli.py | 16 +++--- 2 files changed, 76 insertions(+), 52 deletions(-) diff --git a/doc/cli.rst b/doc/cli.rst index 7a1393a859..7341da56a8 100644 --- a/doc/cli.rst +++ b/doc/cli.rst @@ -8,7 +8,6 @@ Our goal is that the *semantics* of all commands are similar, so that interactin .. contents:: :local: - Controlling CLI behaviour ========================= @@ -16,8 +15,9 @@ To support a variety of complex use-cases, the MESSAGEix stack takes configurati :mod:`ixmp` configuration file: :file:`config.json` --------------------------------------------------- + :mod:`ixmp` keeps track of named Platforms and their associated databases, and stores information in its :file:`config.json` file. -See :mod:`ixmp.config`. +See :ref:`ixmp:configuration` in the documentation. List existing platforms:: $ ixmp platform list @@ -27,15 +27,29 @@ To add a specific database, you can use the ixmp CLI [1]_:: $ ixmp platform add [PLATFORMNAME] jdbc oracle [COMPUTER]:[PORT]/[SERVICENAME] [USERNAME] [PASSWORD] You may also want to make this the *default* platform. -Unless told otherwise, :mod:`message_ix_models` creates :class:`~ixmp.Platform` objects without any arguments (``mp = ixmp.Platform()``); this loads the default platform. +Unless told otherwise, :mod:`message_ix_models` creates :class:`~ixmp.Platform` objects without any arguments (:py:`mp = ixmp.Platform()`); this loads the default platform. Set the default:: $ ixmp platform add default [PLATFORMNAME] -:mod:`message_ix` stores only one configuration value in :file:`config.json`: ``'message model dir'``, the path to the GAMS model files. -MESSAGEix-GLOBIOM uses the GAMS model files from the current :mod:`message_ix` ``master`` branch, so you should not set this, or unset it when using :mod:`message_ix_models`. +:mod:`message_ix` recognizes the following :file:`config.json` value: + +``message_model_dir`` + Path to the GAMS model files. + Most code in MESSAGEix-GLOBIOM expects the GAMS model files from the current :mod:`message_ix` ``main`` branch, so you should not set this, or unset it when using :mod:`message_ix_models`. + +:mod:`message_ix_models` recognizes the following 2 :file:`config.json` values: + +``message_local_data`` + Path to local data, if it is set and not overridden. +``no_message_data`` + If not set or :any:`False`, then the CLI displays a warning message if the private :mod:`message_data` package is not installed:: -:mod:`message_ix_models` will use the :file:`config.json` value ``"message_local_data"`` for local data, if it is set and not overridden. + Warning: message_data is not installed or cannot be imported; see the documentation via --help + + If set to :any:`True`, then the message is suppressed:: + + $ mix-models config set no_message_data true .. [1] ``[COMPUTER]`` is in this case either the hostname or the IP address. @@ -46,7 +60,6 @@ For example, ixmp responds to ``IXMP_DATA``, which tells it where to find the fi :mod:`message_ix_models` responds to ``MESSAGE_LOCAL_DATA``; see :ref:`the discussion of local data `. - CLI parameters (arguments and options) -------------------------------------- @@ -63,12 +76,12 @@ Consider the following examples:: In these examples: -- ``--opt0`` is an option that (potentially) affects **any** command, including the subcommands ``cmd2`` or ``cmd3``. -- ``--opt1`` and ``arg1`` are an option and mandatory argument to the command ``cmd1``. - They might not have any relevance to other ``mix-data`` commands. -- ``cmd2`` and ``cmd3`` are distinct subcommands of ``cmd1``. +- :program:`--opt0` is an option that (potentially) affects **any** command, including the subcommands :program:`cmd2` or :program:`cmd3`. +- :program:`--opt1` and :program:`arg1` are an option and mandatory argument to the command :program:`cmd1`. + They might not have any relevance to other :program:`mix-models` commands. +- :program:`cmd2` and :program:`cmd3` are distinct subcommands of :program:`cmd1`. - - They *may* respond to ``--opt1`` and ``arg1``, and to ``--opt0``; at least, they *must* not contradict them. + - They *may* respond to :program:`--opt1` and :program:`arg1`, and to :program:`--opt0`; at least, they *must* not contradict them. - They each may have their own options and arguments, which can be distinct. .. tip:: Use ``--help`` for any (sub)command to read about its behaviour. @@ -80,7 +93,7 @@ For some features of the code, the default behaviour is very elaborate and serve This default behaviour or optional behaviour is defined by reading an input file. These are stored in the :ref:`package data ` directory. -For example, ``mix-models report`` loads reporting configuration from :file:`message_ix_models/data/report/global.yaml`, a YAML file with hundreds of lines. +For example, :program:`mix-models report` loads reporting configuration from :file:`message_ix_models/data/report/global.yaml`, a YAML file with hundreds of lines. Optionally, a different file can be used:: $ mix-models report --config other @@ -99,77 +112,86 @@ Important CLI options and commands Top-level options and commands ------------------------------ -``mix-models --help`` describes these:: +:program:`mix-models --help` describes these:: - $ mix-models --help Usage: mix-models [OPTIONS] COMMAND [ARGS]... Command-line interface for MESSAGEix-GLOBIOM model tools. Every tool and script in this repository is accessible through this CLI. Scripts are grouped into commands and sub-commands. For help on specific - (sub)commands, use --help, e.g.: + (sub)commands, use --help, for instance: - mix-models cd-links --help - mix-models cd-links run --help + mix-models report --help + mix-models ssp gen-structures --help The top-level options --platform, --model, and --scenario are used by - commands that access specific message_ix scenarios; these can also be - specified with --url. + commands that access specific MESSAGEix scenarios in a specific ixmp + platform/database; these can also be specified with --url. - For more information, see - https://docs.messageix.org/projects/models2/en/latest/cli.html + For complete documentation, see + https://docs.messageix.org/projects/models/en/latest/cli.html Options: --url ixmp://PLATFORM/MODEL/SCENARIO[#VERSION] Scenario URL. - --platform PLATFORM Configured platform name. + --platform PLATFORM ixmp platform name. --model MODEL Model name for some commands. --scenario SCENARIO Scenario name for some commands. - --version INTEGER Scenario version. + --version INTEGER Scenario version for some commands. --local-data PATH Base path for local data. -v, --verbose Print DEBUG-level log messages. --help Show this message and exit. Commands: - cd-links CD-LINKS project. - dl Retrieve data from primary sources. - engage ENGAGE project. - iiasapp Import power plant capacity. - material Model with materials accounting. - prep-submission Prepare scenarios for submission to database. - report Postprocess results. - res MESSAGE-GLOBIOM reference energy system (RES). - techs Export data from data/technology.yaml to CSV. - transport MESSAGEix-Transport variant. - -To explain further: - -``--platform PLATFORM`` or ``--url`` + buildings MESSAGEix-Buildings model. + cd-links CD-LINKS project. + config Get and set configuration keys. + covid COVID project. + engage ENGAGE project. + export-test-data Prepare data for testing. + fetch Retrieve data from primary sources. + iiasapp Import power plant capacity. + last-log Show the location of the last log file, if any. + material Model with materials accounting. + model MESSAGEix-GLOBIOM reference energy system (RES). + navigate NAVIGATE project. + prep-submission Prepare scenarios for submission to an IIASA Scenario... + report Postprocess results. + res MESSAGEix-GLOBIOM reference energy system (RES). + ssp Shared Socioeconomic Pathways (SSP) project. + techs Export metadata to technology.csv. + testing Manipulate test data. + transport MESSAGEix-Transport variant. + water-ix MESSAGEix-Water and Nexus variant. + +Further information about the top-level options: + +:program:`--platform PLATFORM` or :program:`--url` By default, message_data connects to the default ixmp Platform. These options direct it to work with a different Platform. -``--model MODEL --scenario SCENARIO`` or ``--url`` +:program:`--model MODEL --scenario SCENARIO` or :program:`--url` Many commands use an *existing* |Scenario| as a starting point, and begin by cloning that Scenario to a new (model name, scenario name). For any such command, these top-level options define the starting point/initial Scenario to clone/‘baseline’. - In contrast, see ``--output-model``, below. - + In contrast, see :program:`--output-model`, below. Common options -------------- + Since :mod:`message_ix_models.model` and :mod:`message_ix_models.project` codes often perform similar tasks, their CLI options and arguments are provided in :mod:`.util.click` for easy re-use. These include: -``ssp`` argument +:program:`SSP` argument This takes one of the values 'SSP1', 'SSP2', or 'SSP3'. Commands that will not work for one or more of the SSPs should check the argument value given by the user and raise :class:`NotImplementedError`. -``--output-model NAME`` option - This option is a counterpart to the top-level ``--url/--model/--scenario`` options. +:program:`--output-model NAME` option + This option is a counterpart to the top-level :program:`--url`, :program:`--model`, or :program:`--scenario` options. A command that starts from one Scenario, and builds one or more Scenarios from it will clone *to* a new (model name, scenario name); - ``--output-model`` gives the model name. + :program:`--output-model` gives the model name. Current code generates a variety of fixed (non-configurable) scenario names; use ``--help`` for each command to see which. diff --git a/message_ix_models/cli.py b/message_ix_models/cli.py index db818ca7f7..89333a3803 100644 --- a/message_ix_models/cli.py +++ b/message_ix_models/cli.py @@ -2,16 +2,18 @@ Every tool and script in this repository is accessible through this CLI. Scripts are grouped into commands and sub-commands. For help on specific (sub)commands, use --help, -e.g.: +for instance: \b - mix-models cd-links --help - mix-models cd-links run --help + mix-models report --help + mix-models ssp gen-structures --help The top-level options --platform, --model, and --scenario are used by commands that -access specific message_ix scenarios; these can also be specified with --url. +access specific MESSAGEix scenarios in a specific ixmp platform/database; these can also +be specified with --url. -For more information, see https://docs.messageix.org/projects/models/en/latest/cli.html +For complete documentation, see +https://docs.messageix.org/projects/models/en/latest/cli.html """ import logging @@ -35,7 +37,7 @@ @click.option( "--url", metavar="ixmp://PLATFORM/MODEL/SCENARIO[#VERSION]", help="Scenario URL." ) -@click.option("--platform", metavar="PLATFORM", help="Configured platform name.") +@click.option("--platform", metavar="PLATFORM", help="ixmp platform name.") @click.option( "--model", "model_name", metavar="MODEL", help="Model name for some commands." ) @@ -45,7 +47,7 @@ metavar="SCENARIO", help="Scenario name for some commands.", ) -@click.option("--version", type=int, help="Scenario version.") +@click.option("--version", type=int, help="Scenario version for some commands.") @click.option("--local-data", type=Path, help="Base path for local data.") @common_params("verbose") @click.pass_context From 5e877d9b2d65a166325edcda32bccd4622c612c5 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Fri, 15 Mar 2024 15:16:55 +0100 Subject: [PATCH 39/54] Prevent ixmp4 from removing root log handlers --- message_ix_models/util/__init__.py | 7 ++++++- message_ix_models/util/_logging.py | 21 ++++++++++++++++++++- 2 files changed, 26 insertions(+), 2 deletions(-) diff --git a/message_ix_models/util/__init__.py b/message_ix_models/util/__init__.py index e5dd980fc9..5b1b3d358b 100644 --- a/message_ix_models/util/__init__.py +++ b/message_ix_models/util/__init__.py @@ -681,10 +681,15 @@ def show_versions() -> str: from io import StringIO from . import ixmp + from ._logging import preserve_log_handlers # Retrieve package versions buf = StringIO() - ixmp.show_versions(buf) + + # show_versions() imports pyam-iamc, which in turn imports ixmp4, which removes all + # handlers from the root logger (?!). Preserve the message-ix-models logging config. + with preserve_log_handlers(): + ixmp.show_versions(buf) return buf.getvalue() diff --git a/message_ix_models/util/_logging.py b/message_ix_models/util/_logging.py index ba0b63fed0..878bfdb925 100644 --- a/message_ix_models/util/_logging.py +++ b/message_ix_models/util/_logging.py @@ -11,7 +11,7 @@ from datetime import datetime, timedelta, timezone from queue import SimpleQueue from time import process_time -from typing import Dict, List, Union, cast +from typing import Dict, List, Optional, Union, cast # NB mark_time, preserve_log_level, and silence_log are exposed by util/__init__.py __all__ = [ @@ -200,6 +200,25 @@ def mark_time(quiet: bool = False) -> None: ) +@contextmanager +def preserve_log_handlers(name: Optional[str] = None): + """Context manager to preserve the handlers of a `logger`.""" + # Access the named logger + logger = logging.getLogger(name) + # Make a copy of its list of handlers + handlers = list(logger.handlers) + + try: + yield + finally: + # Make a list of handlers which have disappeared from the logger + to_restore = list(filter(lambda h: h not in logger.handlers, handlers)) + for h in to_restore: + logger.addHandler(h) + # Log after the handlers have been restored + log.debug(f"Restore to {logger}.handlers: {to_restore or '(none)'}") + + @contextmanager def preserve_log_level(): """Context manager to preserve the level of the ``message_ix_models`` logger.""" From 8cda4aea8cdbf8e4815ecc9f6d6532c1bd812f2b Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Fri, 15 Mar 2024 15:30:00 +0100 Subject: [PATCH 40/54] Improve mix_models_cli fixture/CliRunner - Move CliRunner to .util.click - Add method="click" / "subprocess" switch. - Add .invoke_subprocess() to use subprocess.run() for stronger isolation of command. - Separate temporary_command() to a stand-alone function. - Remove .add_command(). - Simplify mix_models_cli fixture usage. - Move cli_test_group to .cli with command(s) to be use in subprocess. --- message_ix_models/cli.py | 24 +++++ message_ix_models/testing/__init__.py | 92 +++---------------- message_ix_models/tests/util/test_logging.py | 15 +-- message_ix_models/util/click.py | 97 +++++++++++++++++++- 4 files changed, 137 insertions(+), 91 deletions(-) diff --git a/message_ix_models/cli.py b/message_ix_models/cli.py index 89333a3803..a80791e4de 100644 --- a/message_ix_models/cli.py +++ b/message_ix_models/cli.py @@ -130,6 +130,26 @@ def debug(ctx): log.debug(ctx.local_data) +@main.group("_test", hidden=True) +def cli_test_group(): + """Hidden group of CLI commands. + + Other code which needs to test CLI behaviour **may** attach temporary/throw-away + commands to this group and then invoke them using :func:`mix_models_cli`. This + avoids the need to expose additional commands for testing purposes only. + """ + + +@cli_test_group.command("log-threads") +@click.argument("k", type=int) +@click.argument("N", type=int) +def _log_threads(k: int, n: int): + # Emit many log records + log = logging.getLogger("message_ix_models") + for i in range(n): + log.info(f"{k = } {i = }") + + # Attach the ixmp "config" CLI main.add_command(ixmp_cli.commands["config"]) @@ -185,3 +205,7 @@ def debug(ctx): continue main.add_command(cmd) + + +if __name__ == "__main__": + main() diff --git a/message_ix_models/testing/__init__.py b/message_ix_models/testing/__init__.py index 971e2fe2b1..e3e5e52ff5 100644 --- a/message_ix_models/testing/__init__.py +++ b/message_ix_models/testing/__init__.py @@ -1,21 +1,19 @@ import logging import os from base64 import b32hexencode -from contextlib import contextmanager from copy import deepcopy from pathlib import Path from random import randbytes from tempfile import TemporaryDirectory -import click.testing import message_ix import pandas as pd import pytest from ixmp import Platform from ixmp import config as ixmp_config -from message_ix_models import cli, util -from message_ix_models.util._logging import mark_time, preserve_log_level +from message_ix_models import util +from message_ix_models.util._logging import mark_time from message_ix_models.util.context import Context log = logging.getLogger(__name__) @@ -148,84 +146,22 @@ def user_context(request): # pragma: no cover raise NotImplementedError -class CliRunner(click.testing.CliRunner): - """Subclass of :class:`click.testing.CliRunner` with extra features.""" - - # NB decorator ensures any changes that the CLI makes to the logger level are - # restored - @preserve_log_level() - def invoke(self, *args, **kwargs): - """Invoke the :program:`mix-models` CLI.""" - result = super().invoke(cli.main, *args, **kwargs) - - # Store the result to be used by assert_exit_0() - self.last_result = result - - return result - - def assert_exit_0(self, *args, **kwargs): - """Assert a result has exit_code 0, or print its traceback. - - If any `args` or `kwargs` are given, :meth:`.invoke` is first called. Otherwise, - the result from the last call of :meth:`.invoke` is used. - - Raises - ------ - AssertionError - if the result exit code is not 0. The exception contains the traceback from - within the CLI. - - Returns - ------- - click.testing.Result - """ - __tracebackhide__ = True - - if len(args) + len(kwargs): - self.invoke(*args, **kwargs) - - # Retrieve the last result - result = self.last_result - - if result.exit_code != 0: - print(f"{result.exit_code = }\nresult.output =\n{result.output}") - # Re-raise the exception triggered within the CLI invocation - raise (result.exc_info[1].__context__ or result.exc_info[1]) from None - - return result - - @property - def add_command(self): - return cli_test_group.add_command - - @contextmanager - def temporary_command(self, func: "click.Command", set_target: bool = True): - """Temporarily attach command `func` to :func:`cli_test_group`.""" - assert func.name is not None - try: - cli_test_group.add_command(func) - yield - finally: - cli_test_group.commands.pop(func.name) - - @pytest.fixture -def mix_models_cli(request, test_context, tmp_env): - """A :class:`.CliRunner` object that invokes the :program:`mix-models` CLI.""" - # Require the `test_context` fixture in order to (a) set Context.local_data and (b) - # ensure changes to the Context from tested CLI commands are isolated from other - # tests - yield CliRunner(env=tmp_env) +def mix_models_cli(session_context, tmp_env): + """A :class:`.CliRunner` object that invokes the :program:`mix-models` CLI. + NB this requires: -@cli.main.group("_test", hidden=True) -def cli_test_group(): - """Hidden group of CLI commands. - - Other code which needs to test CLI behaviour **may** attach temporary/throw-away - commands to this group and then invoke them using :func:`mix_models_cli`. This - avoids the need to expose additional commands for testing purposes only. + - The :mod:`ixmp` :func:`.tmp_env` fixture. This sets ``IXMP_DATA`` to a temporary + directory managed by :mod:`pytest`. + - The :func:`session_context` fixture. This (a) sets :attr:`.Config.local_data` to + a temporary directory within ``IXMP_DATA`` and (b) ensures changes to + :class:`.Context` made by invoked commands do not reach other tests. """ + from message_ix_models import cli + from message_ix_models.util.click import CliRunner + + yield CliRunner(cli.main, cli.__name__, env=tmp_env) # Testing utility functions diff --git a/message_ix_models/tests/util/test_logging.py b/message_ix_models/tests/util/test_logging.py index 5a21f90bfd..6ee330a268 100644 --- a/message_ix_models/tests/util/test_logging.py +++ b/message_ix_models/tests/util/test_logging.py @@ -1,7 +1,6 @@ import logging import re -import click import pytest from message_ix_models.util._logging import mark_time, silence_log @@ -38,15 +37,11 @@ def test_flush(self, caplog, mix_models_cli, k): and captured by the :class:`.CliRunner`. """ - @click.command("log-threads") - def func(): - # Emit many log records - log = logging.getLogger("message_ix_models") - [log.info(f"{k = } {i = }") for i in range(self.N)] - - with mix_models_cli.temporary_command(func): - # Run the command, capture output - result = mix_models_cli.assert_exit_0(["_test", func.name]) + # Run the command, capture output + # See message_ix_models.cli._log_threads + result = mix_models_cli.assert_exit_0( + ["_test", "log-threads", str(k), str(self.N)], method="click" + ) # All records are emitted; the last record ends with N - 1 assert result.output.rstrip().endswith(f"{self.N - 1}"), result.output.split( diff --git a/message_ix_models/util/click.py b/message_ix_models/util/click.py index 5760fd34f9..830c3247cc 100644 --- a/message_ix_models/util/click.py +++ b/message_ix_models/util/click.py @@ -4,16 +4,21 @@ """ import logging +import sys +from contextlib import contextmanager +from dataclasses import dataclass, field from datetime import datetime from pathlib import Path -from typing import Callable, List, Optional, Union +from typing import Callable, List, Literal, Mapping, Optional, Union, cast import click +import click.testing from click import Argument, Choice, Option from message_ix_models import Context, model from message_ix_models.model.structure import codelists +from ._logging import preserve_log_level from .scenarioinfo import ScenarioInfo log = logging.getLogger(__name__) @@ -88,8 +93,6 @@ def _cb(context: Union[click.Context, Context], param, value): def format_sys_argv() -> str: """Format :data:`sys.argv` in a readable manner.""" - import sys - lines = ["Invoked:"] indent = "" for item in sys.argv: @@ -113,6 +116,17 @@ def store_context(context: Union[click.Context, Context], param, value): return value +@contextmanager +def temporary_command(group: "click.Group", command: "click.Command"): + """Temporarily attach command `command` to `group`.""" + assert command.name is not None + try: + group.add_command(command) + yield + finally: + group.commands.pop(command.name) + + def urls_from_file( context: Union[click.Context, Context], param, value ) -> List[ScenarioInfo]: @@ -262,3 +276,80 @@ def unique_id() -> str: # expose_value=False, ), } + + +@dataclass +class CliRunner: + """Similar to :class:`click.testing.CliRunner`, with extra features.""" + + #: CLI entry point + cli_cmd: click.Command + #: CLI module + cli_module: str + + env: Mapping[str, str] = field(default_factory=dict) + charset: str = "utf-8" + + #: Method for invoking the command + method: Literal["click", "subprocess"] = "click" + + def invoke(self, *args, **kwargs) -> click.testing.Result: + method = kwargs.pop("method", self.method) + + if method == "click": + runner = click.testing.CliRunner(env=self.env) + with preserve_log_level(): + result = runner.invoke(self.cli_cmd, *args, **kwargs) + elif method == "subprocess": + result = self.invoke_subprocess(*args, **kwargs) + + # Store the result to be used by assert_exit_0() + self.last_result = result + + return result + + def invoke_subprocess(self, *args, **kwargs) -> click.testing.Result: + """Invoke the CLI in a subprocess.""" + import subprocess + + assert 1 == len(args) + all_args: List[str] = [sys.executable, "-m", self.cli_module, *args[0]] + + # Run; capture in a subprocess.CompletedProcess + cp = subprocess.run(all_args, capture_output=True, env=self.env, **kwargs) + + # Convert to a click.testing.Result + return click.testing.Result( + runner=cast(click.testing.CliRunner, self), + stdout_bytes=cp.stdout or bytes(), + stderr_bytes=cp.stderr or bytes(), + return_value=None, + exit_code=cp.returncode, + exception=None, + exc_info=None, + ) + + def assert_exit_0(self, *args, **kwargs) -> click.testing.Result: + """Assert a result has exit_code 0, or print its traceback. + + If any `args` or `kwargs` are given, :meth:`.invoke` is first called. Otherwise, + the result from the last call of :meth:`.invoke` is used. + + Raises + ------ + AssertionError + if the result exit code is not 0. + """ + __tracebackhide__ = True + + if len(args) + len(kwargs): + self.invoke(*args, **kwargs) + + # Retrieve the last result + result = self.last_result + + if result.exit_code != 0: + print(f"{result.exit_code = }", f"{result.output = }", sep="\n") + raise RuntimeError(result.exit_code) + + return result From 653c8584130362071194599a0644573dbfe5facf Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Fri, 15 Mar 2024 15:30:50 +0100 Subject: [PATCH 41/54] Parametrize TestQueueListener.test_flush() --- message_ix_models/tests/util/test_logging.py | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/message_ix_models/tests/util/test_logging.py b/message_ix_models/tests/util/test_logging.py index 6ee330a268..5f2d186c43 100644 --- a/message_ix_models/tests/util/test_logging.py +++ b/message_ix_models/tests/util/test_logging.py @@ -26,8 +26,12 @@ class TestQueueListener: #: Number of times to run the test. k = 4 + @pytest.mark.parametrize( + "method", + ("click", pytest.param("subprocess", marks=pytest.mark.skip(reason="Slow."))), + ) @pytest.mark.parametrize("k", range(k)) - def test_flush(self, caplog, mix_models_cli, k): + def test_flush(self, caplog, mix_models_cli, method, k): """Test logging in multiple processes, multiple threads, and with :mod:`click`. With pytest-xdist, these :attr:`k` test cases will run in multiple processes. @@ -40,7 +44,7 @@ def test_flush(self, caplog, mix_models_cli, k): # Run the command, capture output # See message_ix_models.cli._log_threads result = mix_models_cli.assert_exit_0( - ["_test", "log-threads", str(k), str(self.N)], method="click" + ["_test", "log-threads", str(k), str(self.N)], method=method ) # All records are emitted; the last record ends with N - 1 From 3fa1175afee2c1341673efceb9b96ea32959ae69 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Fri, 15 Mar 2024 15:40:10 +0100 Subject: [PATCH 42/54] Streamline .util._logging.setup() and related - Reduce QueueHandler to a typing stub. - Use a function rather than logging.config.dictConfig(). - Set root logger level to DEBUG. --- message_ix_models/util/_logging.py | 161 +++++++++++------------------ 1 file changed, 58 insertions(+), 103 deletions(-) diff --git a/message_ix_models/util/_logging.py b/message_ix_models/util/_logging.py index 878bfdb925..bce5d2fd68 100644 --- a/message_ix_models/util/_logging.py +++ b/message_ix_models/util/_logging.py @@ -7,67 +7,24 @@ import sys import time from contextlib import contextmanager -from copy import deepcopy from datetime import datetime, timedelta, timezone from queue import SimpleQueue from time import process_time -from typing import Dict, List, Optional, Union, cast +from typing import Dict, Optional, Union, cast # NB mark_time, preserve_log_level, and silence_log are exposed by util/__init__.py __all__ = [ "Formatter", - "QueueHandler", + "QueueListener", "StreamHandler", "setup", ] log = logging.getLogger(__name__) +# References to handlers _HANDLER: Dict[str, logging.Handler] = dict() -# NB This is only separate to avoid complaints from mypy -_HANDLER_CONFIG = dict( - console={ - "class": "message_ix_models.util._logging.StreamHandler", - "level": 99, - "formatter": "color", - "stream_name": "stdout", - }, - file={ - "class": "logging.FileHandler", - "level": 99, - "formatter": "plain", - "delay": True, - }, - queue={ - "class": "message_ix_models.util._logging.QueueHandler", - "handlers": ["console", "file"], - "respect_handler_level": True, - }, -) - -_CONFIG = dict( - version=1, - disable_existing_loggers=False, - formatters=dict( - color={"()": "message_ix_models.util._logging.Formatter"}, - plain={"()": "message_ix_models.util._logging.Formatter", "use_colour": False}, - ), - handlers=_HANDLER_CONFIG, - loggers={ - # Ensure no level set for these packages; the level of the "console"/"file" - # handlers determines outputs - "message_ix_models": dict(level=logging.NOTSET), - "message_data": dict(level=logging.NOTSET), - # Hide DEBUG messages for some upstream packages from the file log - "graphviz._tools": dict(level=logging.DEBUG + 1), - "pycountry.db": dict(level=logging.DEBUG + 1), - "matplotlib.backends": dict(level=logging.DEBUG + 1), - "matplotlib.font_manager": dict(level=logging.DEBUG + 1), - }, - root=dict(handlers=["queue"]), -) - # For mark_time() _TIMES = [] @@ -78,8 +35,7 @@ class Formatter(logging.Formatter): Parameters ---------- use_color : bool, *optional* - If :any:`True`, :mod:`colorama` is used to colour log messages printed to - stdout. + If :any:`True`, :mod:`colorama` is used to colour log messages. """ CYAN = "" @@ -109,7 +65,7 @@ def format(self, record): Records are formatted like:: model.transport.data.add_par_data 220 rows in 'input' - ...add_par_data: further messages + ...add_par_data further messages …with the calling function name (e.g. 'add_par_data') coloured for legibility on first occurrence, then dimmed when repeated. @@ -131,34 +87,9 @@ def format(self, record): class QueueHandler(logging.handlers.QueueHandler): - """Queue handler with custom set-up. - - This emulates the default behaviour available in Python 3.12 for Python 3.11 and - earlier; it is also compatible with Python 3.12. - """ - - #: Corresponding listener that dispatches to the actual handlers. + # For typing with Python ≤ 3.11 only; from 3.12 this attribute is described listener: "QueueListener" - def __init__( - self, - queue=None, # For Python 3.12 - *, - handlers: List[str] = [], # For Python 3.11 and earlier - respect_handler_level: bool = False, - ) -> None: - super().__init__(queue or SimpleQueue()) - - # Construct the listener - # NB This relies on the non-public collection logging._handlers - self.listener = QueueListener( - self.queue, - *[logging._handlers[name] for name in handlers], # type: ignore [attr-defined] - respect_handler_level=respect_handler_level, - ) - self.listener.start() - atexit.register(self.listener.stop) - class QueueListener(logging.handlers.QueueListener): """:class:`.logging.QueueListener` with a :meth:`.flush` method.""" @@ -171,7 +102,7 @@ def flush(self): class StreamHandler(logging.StreamHandler): - """Like :class:`.logging.StreamHandler`, but refresh sys.stdout on each access. + """Like :class:`.logging.StreamHandler`, but retrieve the stream on each access. This avoids the case that :mod:`click`, :mod:`pytest`, or something else adjusts :py:`sys.stdout` temporarily, but the handler's stored reference to the original is @@ -234,7 +165,55 @@ def preserve_log_level(): main_log.setLevel(level) -_HANDLER = dict() +def configure(): + """Apply logging configuration.""" + # NB We do this programmatically as logging.config.dictConfig()'s automatic steps + # require adjustments that end up being more verbose and less clear. + from platformdirs import user_log_path + + # Stream handler + _HANDLER["console"] = h_console = StreamHandler(stream_name="stdout") + h_console.setLevel(logging.CRITICAL) + h_console.setFormatter(Formatter()) + + # Construct the file name for the log file + log_file_path = user_log_path("message-ix-models", ensure_exists=True).joinpath( + datetime.now(timezone(timedelta(seconds=time.timezone))) + .isoformat(timespec="seconds") + .replace(":", "") + ) + + # File handler + _HANDLER["file"] = h_file = logging.FileHandler( + filename=str(log_file_path), delay=True + ) + h_file.setLevel(logging.CRITICAL) + h_file.setFormatter(Formatter(use_colour=False)) + + # Queue handler + queue = SimpleQueue() + _HANDLER["queue"] = h_queue = QueueHandler(queue) + logging.root.addHandler(h_queue) + + # Queue listener + h_queue.listener = listener = QueueListener( + queue, h_console, h_file, respect_handler_level=True + ) + listener.start() + atexit.register(listener.stop) + + for name, level in ( + (None, logging.DEBUG), + # Ensure no level set for these packages; the level of the "console"/"file" + # handlers determines outputs + ("message_ix_models", logging.NOTSET), + ("message_data", logging.NOTSET), + # Hide lower-level messages for some upstream packages from the file log + ("graphviz._tools", logging.WARNING), + ("matplotlib", logging.WARNING), + ("pycountry.db", logging.WARNING), + ): + logging.getLogger(name).setLevel(level) def setup( @@ -254,38 +233,14 @@ def setup( file : bool, *optional* If :obj:`False`, do not print any messages to file. """ - from platformdirs import user_log_path root = logging.getLogger() - if not any(isinstance(h, QueueHandler) for h in root.handlers): + if not any(isinstance(h, logging.handlers.QueueHandler) for h in root.handlers): # Not yet configured - - # Construct the file name for the log file - log_file_path = user_log_path("message-ix-models", ensure_exists=True).joinpath( - datetime.now(timezone(timedelta(seconds=time.timezone))) - .isoformat(timespec="seconds") - .replace(":", "") - ) - - # Copy and modify dictionaries - config_handlers = deepcopy(_HANDLER_CONFIG) - config_handlers["file"].update(filename=log_file_path) - config = deepcopy(_CONFIG) - config.update(handlers=config_handlers) - - # Apply the configuration - logging.config.dictConfig(config) + configure() # Apply settings to loggers and handlers: either just-created, or pre-existing - # Identify the QueueHandler instance - queue_handler = next(filter(lambda qh: isinstance(qh, QueueHandler), root.handlers)) - assert isinstance(queue_handler, QueueHandler) - _HANDLER.update(queue=queue_handler) - - # Prepare a dictionary of the listener's handlers - _HANDLER.update({str(h.name): h for h in queue_handler.listener.handlers}) - # Set the level of the console handler _HANDLER["console"].setLevel(99 if console is False else level) From 9e228ffa2ae6e953d7b630158c7b1ca8b675070e Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Fri, 15 Mar 2024 15:43:04 +0100 Subject: [PATCH 43/54] Implement silence_log() using a filter - Filters and levels on e.g. "message_ix_models" logger are not effective when handlers are attached at the root.; cf. https://stackoverflow.com/a/17276457 - Warn and adjust usage where names= is list of str. --- message_ix_models/report/__init__.py | 2 +- message_ix_models/util/_logging.py | 53 ++++++++++++++++++---------- 2 files changed, 36 insertions(+), 19 deletions(-) diff --git a/message_ix_models/report/__init__.py b/message_ix_models/report/__init__.py index edcab1df5f..f50d2cc46f 100644 --- a/message_ix_models/report/__init__.py +++ b/message_ix_models/report/__init__.py @@ -246,7 +246,7 @@ def report(context: Context, *args, **kwargs): with ( nullcontext() if context.core.verbose - else silence_log(["genno", "message_ix_models"]) + else silence_log("genno message_ix_models") ): rep, key = prepare_reporter(context) diff --git a/message_ix_models/util/_logging.py b/message_ix_models/util/_logging.py index bce5d2fd68..7dc575d128 100644 --- a/message_ix_models/util/_logging.py +++ b/message_ix_models/util/_logging.py @@ -4,6 +4,7 @@ import logging import logging.config import logging.handlers +import re import sys import time from contextlib import contextmanager @@ -11,11 +12,13 @@ from queue import SimpleQueue from time import process_time from typing import Dict, Optional, Union, cast +from warnings import warn # NB mark_time, preserve_log_level, and silence_log are exposed by util/__init__.py __all__ = [ "Formatter", "QueueListener", + "SilenceFilter", "StreamHandler", "setup", ] @@ -101,6 +104,20 @@ def flush(self): self.start() +class SilenceFilter(logging.Filter): + """Log filter that only allows records from `names` that are at or above `level`.""" + + __slots__ = ("level", "name_expr") + + def __init__(self, names: str, level: int): + self.level = level + # Compile a regular expression for the name + self.name_re = re.compile("|".join(map(re.escape, sorted(names.split())))) + + def filter(self, record) -> bool: + return not (record.levelno < self.level and self.name_re.match(record.name)) + + class StreamHandler(logging.StreamHandler): """Like :class:`.logging.StreamHandler`, but retrieve the stream on each access. @@ -257,7 +274,7 @@ def flush() -> None: @contextmanager -def silence_log(names=None, level=logging.ERROR): +def silence_log(names: Optional[str] = None, level: int = logging.ERROR): """Context manager to temporarily quiet 1 or more loggers. Parameters @@ -272,26 +289,26 @@ def silence_log(names=None, level=logging.ERROR): >>> with silence_log(): >>> log.warning("This message is not recorded.") """ - # Default: the top-level logger for the package containing this file - if names is None: - names = [__name__.split(".")[0], "message_data"] - elif isinstance(names, str): - names = [names] - - log.info(f"Set level={level} for logger(s): {' '.join(names)}") + if isinstance(names, list): + warn( + "silence_log(names=…) as list of str; use a single, space-separated str", + DeprecationWarning, + stacklevel=2, + ) + names = " ".join(names) - # Retrieve the logger objects - loggers = list(map(logging.getLogger, names)) - # Store their current levels - levels = [] + # Create a filter; default, the top-level logger for the current package + f = SilenceFilter(names or f"message_data {__name__.split('.')[0]}", level) + log.info(f"Set level={level} for logger(s): {f.name_re.pattern.replace('|', ' ')}") try: - for logger in loggers: - levels.append(logger.getEffectiveLevel()) # Store the current levels - logger.setLevel(level) # Set the level + # Add the same filter to every handler of the root logger + for handler in logging.root.handlers: + handler.addFilter(f) + yield finally: - # Restore the levels - for logger, original_level in zip(loggers, levels): - logger.setLevel(original_level) + # Remove the filter + for handler in logging.root.handlers: + handler.removeFilter(f) log.info("…restored.") From c2d527987968061c5cf667ded49066726ae88296 Mon Sep 17 00:00:00 2001 From: Paul Natsuo Kishimoto Date: Fri, 15 Mar 2024 15:43:41 +0100 Subject: [PATCH 44/54] Adjust use of temporary_command() in tests --- message_ix_models/tests/test_workflow.py | 46 ++++++++++---------- message_ix_models/tests/util/test_click.py | 11 ++--- message_ix_models/tests/util/test_context.py | 10 +++-- 3 files changed, 36 insertions(+), 31 deletions(-) diff --git a/message_ix_models/tests/test_workflow.py b/message_ix_models/tests/test_workflow.py index 1394fab8f6..af9168a1d2 100644 --- a/message_ix_models/tests/test_workflow.py +++ b/message_ix_models/tests/test_workflow.py @@ -91,34 +91,36 @@ def _wf( def test_make_click_command(mix_models_cli) -> None: import click + from message_ix_models.cli import cli_test_group + from message_ix_models.util.click import temporary_command + # make_click_command() runs and generates a command name = "make-click-command" cmd = make_click_command(f"{__name__}._wf", name=name, slug="test") assert isinstance(cmd, click.Command) # Add this into the hidden CLI test group - mix_models_cli.add_command(cmd) - - # Invoke the command with various parameters - for params, output in ( - (["--go", "B"], "nothing returned, workflow will continue with"), - (["B"], "Workflow diagram written to"), - ): - # Command runs and exits with 0 - result = mix_models_cli.assert_exit_0(["_test", "run"] + params) - # Expected log messages or output were printed - assert output in result.output - - # Invalid usage - for params, output in ( - (["--go", "C"], "Error: No step(s) matched"), - (["--go"], "Error: No target step provided and no default for"), - # Step changes_b() fails if changes_a() is not first run - (["--go", "--from=[AX]", "B"], "Execute