diff --git a/.gitignore b/.gitignore index d4907f7cf..53d94c268 100644 --- a/.gitignore +++ b/.gitignore @@ -342,3 +342,10 @@ src/proteus/_version.py # Local scratch directories (not part of the project) /.playwright-mcp/ /platon/ + +# output logs +*.out + +# test inference tomls +input/test_infer_proteus/ +input/inference/test_infer diff --git a/docs/How-to/inference.md b/docs/How-to/inference.md index 09cc38434..f19e7ec7c 100644 --- a/docs/How-to/inference.md +++ b/docs/How-to/inference.md @@ -32,6 +32,7 @@ The system performs Bayesian optimization to infer planetary formation parameter | `async_BO.py` | Parallel BO implementation | | `BO.py` | Single BO step implementation | | `objective.py` | PROTEUS interface and objective function | + | `failures.py` | Functions for handling failing simulations | | `plot.py` | Visualization utilities | | `utils.py` | Helper functions for inference scheme | | `gen_D_init.py` | Generate initial data | @@ -122,6 +123,7 @@ The system generates several outputs in: - `logs.csv`: Detailed logs of each BO step - `Ts.csv`: Timestamps for performance analysis - `init.csv`: Data used as an initial guess for starting the optimisation +- `failures.csv`: One row per simulation that failed or was excluded, written only when there is at least one (see [Failed and excluded simulations](#failed-and-excluded-simulations)) ### Plots The BO scheme will generate many plots upon completion. @@ -144,10 +146,15 @@ Plots prefixed with `result_` show the results of the optimisation. ### Results Summary The system prints the final results including: + - Best found parameters - Corresponding simulated observables - Comparison with target observables +### Failed and excluded simulations + +During the inference run, some PROTEUS simulations might crash or fail, or stop on a status that is excluded in the inference configuration (e.g. maximum runtime reached). The run carries on when there are failures unless `abort_on_failure` is set to `true` in the inference config. At the end of the study all failures are written to `failures.csv` in the output folder, and summarised. + ## Customization ### Adding New Parameters diff --git a/docs/Reference/config/atmosphere.md b/docs/Reference/config/atmosphere.md index ed985c957..8d905c805 100644 --- a/docs/Reference/config/atmosphere.md +++ b/docs/Reference/config/atmosphere.md @@ -25,6 +25,7 @@ parameter selects the surface energy balance scheme (`mixed_layer`, | `module` | str | `"agni"` | Which atmosphere module to use. Choices: `"dummy"`, `"agni"`, `"janus"`. | | `spectral_group` | str | `"Honeyside"` | Spectral file group defining gas opacities. See https://proteus-framework.org/SOCRATES/Reference/proteus_spectral_file_reference.html. | | `spectral_bands` | str | `"48"` | Number of wavenumber bands in k-table. | +| `spectral_cache` | str or none | `none` | Folder in which to reuse prepared spectral files across runs that share a stellar spectrum. None disables the cache and every run builds its own. | | `num_levels` | int | `50` | Number of vertical atmosphere levels. Must be >= 15. | | `p_top` | float | `1e-06` | Top-of-atmosphere pressure \[bar\]. Must be > 0. | | `p_obs` | float | `0.02` | Observation pressure level \[bar\] (transit radius). Must be > 0. | diff --git a/docs/Reference/config/config_schema.json b/docs/Reference/config/config_schema.json index ef17b0cd2..023a37cb6 100644 --- a/docs/Reference/config/config_schema.json +++ b/docs/Reference/config/config_schema.json @@ -8673,6 +8673,22 @@ "group": null, "group_qualifier": null }, + { + "path": "atmos_clim.spectral_cache", + "toml_section": "atmos_clim", + "class": "AtmosClim", + "type": "str or none", + "accepts_none": true, + "default": "none", + "choices": null, + "bounds": null, + "description": "Folder in which to reuse prepared spectral files across runs that share a stellar spectrum. None disables the cache and every run builds its own.", + "doc_source": "attributes", + "group_order": 0, + "group_position": 3, + "group": null, + "group_qualifier": null + }, { "path": "atmos_clim.num_levels", "toml_section": "atmos_clim", @@ -8690,7 +8706,7 @@ "description": "Number of vertical atmosphere levels.", "doc_source": "attributes", "group_order": 0, - "group_position": 3, + "group_position": 4, "group": null, "group_qualifier": null }, @@ -8711,7 +8727,7 @@ "description": "Top-of-atmosphere pressure [bar].", "doc_source": "attributes", "group_order": 0, - "group_position": 4, + "group_position": 5, "group": null, "group_qualifier": null }, @@ -8732,7 +8748,7 @@ "description": "Observation pressure level [bar] (transit radius).", "doc_source": "attributes", "group_order": 0, - "group_position": 5, + "group_position": 6, "group": null, "group_qualifier": null }, @@ -8748,7 +8764,7 @@ "description": "Gas overlap method. Choices: 'ro', 'rorr', 'ee'.", "doc_source": "attributes", "group_order": 0, - "group_position": 6, + "group_position": 7, "group": null, "group_qualifier": null }, diff --git a/input/all_options.toml b/input/all_options.toml index 9f3851c2a..bcd6ce2fe 100644 --- a/input/all_options.toml +++ b/input/all_options.toml @@ -637,6 +637,7 @@ config_version = "3.0" # Grid and spectral setup (shared by agni + janus) spectral_group = "Honeyside" # opacity k-table set; see docs/assets/spectral_files.pdf spectral_bands = "48" # wavenumber bands in k-table + spectral_cache = "none" # reuse prepared spectral files across runs with the same star; none = off num_levels = 50 # vertical atmosphere levels (min 15) p_top = 1.0e-6 # top-of-atmosphere pressure [bar] p_obs = 0.02 # observation pressure level [bar] (transit radius) diff --git a/input/inference/example.infer.toml b/input/inference/example.infer.toml index 2f68c956c..0ca369634 100644 --- a/input/inference/example.infer.toml +++ b/input/inference/example.infer.toml @@ -10,16 +10,19 @@ logging = "INFO" output = "bayesopt_infer_se_mat12_lei_5_100/" # Path to base (reference) config file relative to PROTEUS root folder -# ref_config = "output/bayesopt_se/init_coupler.toml" ref_config = "input/inference/example.toml" # Method for initialising the inference scheme (one of these must be 'none') init_samps = 3 # Number of random samples if starting from scratch. init_grid = 'none' # grid_demo/' # Path pre-computed grid (relative to PROTEUS output folder) -# Excluded exit codes (in addition to errors) +# Completion codes to exclude from the fit. failure_codes = [11, ] # solidified (10), escaped (15), max_runtime (11) +# Stop the whole inference run at the first simulation that fails, instead of scoring +# it as a poor sample and carrying on. Off by default. +abort_on_failure = false + # Parameters for Bayesian optimisation n_workers = 5 # Number of parallel workers kernel = "MAT1/2" # Kernel type for GP, "RBF" | "MAT1/2" | "MAT3/2" | "MAT5/2" diff --git a/src/proteus/atmos_clim/agni.py b/src/proteus/atmos_clim/agni.py index 58ec581ab..96b216102 100644 --- a/src/proteus/atmos_clim/agni.py +++ b/src/proteus/atmos_clim/agni.py @@ -12,6 +12,7 @@ from scipy.interpolate import PchipInterpolator from proteus.atmos_clim.common import clip_radius_to_hill, get_oarr_from_parr, get_spfile_path +from proteus.atmos_clim.spectral_cache import cache_key, seed_from_cache, store_in_cache from proteus.utils.constants import gas_list, noble_gases from proteus.utils.helper import ( UpdateStatusfile, @@ -484,6 +485,18 @@ def init_agni_atmos(dirs: dict, config: Config, hf_row: dict): # bypass the glob entirely so a missing or empty `data/*.sflux` directory # is not a precondition for those modes. + # Fast I/O folder. Decided before the spectral file, because AGNI writes the + # prepared runtime.sf pair here and so this is where the cache reads from. + if (config.atmos_clim.agni.verbosity >= 2) or (config.params.out.logging == 'DEBUG'): + io_dir = dirs['output'] + else: + io_dir = create_tmp_folder() + log.info(f'Temporary-file working dir: {io_dir}') + + # Set when this run built a prepared spectral file that the cache does not + # yet hold, so it can be stored once the build is known to have succeeded. + cache_store_key = None + # Spectral file path provided? if config.atmos_clim.agni.spectral_file is not None: # Grey gas? @@ -527,12 +540,21 @@ def init_agni_atmos(dirs: dict, config: Config, hf_row: dict): input_sf = get_spfile_path(dirs['fwl'], config) input_star = sflux_path - # Fast I/O folder - if (config.atmos_clim.agni.verbosity >= 2) or (config.params.out.logging == 'DEBUG'): - io_dir = dirs['output'] - else: - io_dir = create_tmp_folder() - log.info(f'Temporary-file working dir: {io_dir}') + # Reuse a cached file built earlier from this base file and this stellar + # spectrum, and skip the insertion. + if config.atmos_clim.spectral_cache: + key = cache_key( + input_sf, + sflux_path, + config.atmos_clim.spectral_group, + config.atmos_clim.spectral_bands, + ) + if seed_from_cache(config.atmos_clim.spectral_cache, key, io_dir): + log.debug('Reusing prepared spectral file from cache') + input_sf = os.path.join(io_dir, 'runtime.sf') + input_star = '' + else: + cache_store_key = key # composition vol_dict = _construct_voldict(config, hf_row, dirs) @@ -665,6 +687,10 @@ def init_agni_atmos(dirs: dict, config: Config, hf_row: dict): # Confirm the live Atmos_t contains every field that PROTEUS expects _check_agni_schema(atmos, dirs) + # Stored spectral file is now valid, so store it in the cache if requested. + if cache_store_key: + store_in_cache(config.atmos_clim.spectral_cache, cache_store_key, io_dir) + # Set temperature profile from old NetCDF if it exists nc_files = glob.glob(os.path.join(dirs['output'], 'data', '*_atm.nc')) if len(nc_files) > 0: diff --git a/src/proteus/atmos_clim/spectral_cache.py b/src/proteus/atmos_clim/spectral_cache.py new file mode 100644 index 000000000..babc91331 --- /dev/null +++ b/src/proteus/atmos_clim/spectral_cache.py @@ -0,0 +1,154 @@ +"""Reuse of prepared spectral files across runs that share a stellar spectrum. + +A run's `runtime.sf` is the base spectral file from FWL_DATA with that run's +stellar spectrum inserted. This module keeps one copy per distinct input set so the +second and later runs copy it instead. + +The cache is seeded into the run's output folder as `runtime.sf`, which is +where the atmosphere wrapper already expects to manage it. +""" + +from __future__ import annotations + +import hashlib +import logging +import os +import shutil +from pathlib import Path + +log = logging.getLogger('fwl.' + __name__) + +# Prepared spectral files come in a pair, and the existence check in the AGNI +# module only tests the first. Seeding one without the other would leave the +# module using a file whose companion is absent. +SPECTRAL_SUFFIXES = ('', '_k') + +# Bytes read per chunk when fingerprinting a file. +_CHUNK = 1 << 20 + + +def _file_digest(path: Path) -> str: + """Hash a file's contents.""" + digest = hashlib.sha256() + with open(path, 'rb') as f: + while chunk := f.read(_CHUNK): + digest.update(chunk) + return digest.hexdigest() + + +def cache_key(base_sf: Path | str, star_spectrum: Path | str, group: str, bands: str) -> str: + """Name the cache entry for a prepared spectral file. The stellar spectrum is hashed by content. + + Parameters + ---------- + - base_sf (Path | str): Base spectral file, from FWL_DATA. + - star_spectrum (Path | str): Stellar spectrum (`.sflux`) to be inserted. + - group (str): Spectral file group. + - bands (str): Number of wavenumber bands. + + Returns + ---------- + - str: Hex digest naming this combination. + """ + base = Path(base_sf) + stat = base.stat() + parts = ( + group, + bands, + base.name, + str(stat.st_size), + str(int(stat.st_mtime)), + _file_digest(Path(star_spectrum)), + ) + return hashlib.sha256('\0'.join(parts).encode()).hexdigest()[:32] + + +def _entry_paths(cache_dir: Path | str, key: str) -> list[Path]: + """Paths of the cached pair for one key.""" + return [Path(cache_dir) / f'{key}.sf{suffix}' for suffix in SPECTRAL_SUFFIXES] + + +def _output_paths(out_dir: Path | str) -> list[Path]: + """Paths of the prepared pair inside a run's output folder.""" + return [Path(out_dir) / f'runtime.sf{suffix}' for suffix in SPECTRAL_SUFFIXES] + + +def seed_from_cache(cache_dir: Path | str, key: str, out_dir: Path | str) -> bool: + """Copy a cached spectral file pair into a run's output folder. + + Parameters + ---------- + - cache_dir (Path | str): Folder holding cached entries. + - key (str): Key from `cache_key`. + - out_dir (Path | str): The run's output folder. + + Returns + ---------- + - bool: True if the run can now use `runtime.sf` as-is. False on a miss, or + on any error: a cache that cannot be read is a slower run, never a failed + one, so the caller falls back to building the file. + """ + entries = _entry_paths(cache_dir, key) + if not all(entry.is_file() for entry in entries): + return False + + targets = _output_paths(out_dir) + try: + Path(out_dir).mkdir(parents=True, exist_ok=True) + for entry, target in zip(entries, targets): + shutil.copyfile(entry, target) + except OSError as err: + log.warning(f'Could not seed spectral file from cache: {err}') + # A half-copied pair would be read as a prepared file. Clear it so the + # run rebuilds from scratch instead of starting from a truncated file. + for target in targets: + try: + target.unlink(missing_ok=True) + except OSError as cleanup_err: + log.debug(f'Could not remove partial spectral file {target}: {cleanup_err}') + return False + + log.debug(f'Seeded spectral file from cache entry {key}') + return True + + +def store_in_cache(cache_dir: Path | str, key: str, out_dir: Path | str) -> bool: + """Copy a run's prepared spectral file pair into the cache. + + Written to a temporary name and renamed into place, so concurrent runs + racing to populate the same key never expose a half-written entry. + + Parameters + ---------- + - cache_dir (Path | str): Folder holding cached entries. + - key (str): Key from `cache_key`. + - out_dir (Path | str): The run's output folder, holding the prepared pair. + + Returns + ---------- + - bool: True if the entry was stored. False if the run produced no prepared + file, or the cache could not be written; neither is a fault of the run. + """ + sources = _output_paths(out_dir) + if not all(source.is_file() for source in sources): + return False + + try: + Path(cache_dir).mkdir(parents=True, exist_ok=True) + for source, entry in zip(sources, _entry_paths(cache_dir, key)): + tmp = entry.with_name(f'{entry.name}.{os.getpid()}.tmp') + try: + shutil.copyfile(source, tmp) + os.replace(tmp, entry) + except Exception: + try: + tmp.unlink(missing_ok=True) + except OSError: + pass + raise + except OSError as err: + log.warning(f'Could not store spectral file in cache: {err}') + return False + + log.debug(f'Stored spectral file in cache as entry {key}') + return True diff --git a/src/proteus/cli.py b/src/proteus/cli.py index f6553b46c..2e27d0282 100644 --- a/src/proteus/cli.py +++ b/src/proteus/cli.py @@ -56,6 +56,7 @@ def _should_apply_deterministic(argv, environ) -> bool: else: os.execvp(sys.argv[0], sys.argv) +import logging # noqa: E402 import shutil # noqa: E402 import subprocess # noqa: E402 import tempfile # noqa: E402 @@ -70,6 +71,8 @@ def _should_apply_deterministic(argv, environ) -> bool: from proteus.utils.helper import get_proteus_dir, resolve_fwl_data_dir # noqa: E402 from proteus.utils.logs import bootstrap_logger, setup_logger # noqa: E402 +log = logging.getLogger('fwl.' + __name__) + config_option = click.option( '-c', '--config', @@ -89,6 +92,20 @@ def _should_apply_deterministic(argv, environ) -> bool: ) +class ConfigRejectedError(click.ClickException): + """A refused configuration, reported at error level on the 'fwl' logger. + + click prints a ClickException as a bare ``Error: ...`` line that carries no + level, so a refusal arrived untagged among the level-tagged lines around + it. Overriding how it is shown keeps everything click gives the caller (no + traceback, exit code 1) while routing the text through the same logger and + formatter as the rest of the run, where it is marked ERROR. + """ + + def show(self, file=None) -> None: + log.error(self.format_message()) + + class ConfigAwareGroup(click.Group): """Command group that presents a refused configuration as a CLI error. @@ -103,7 +120,7 @@ def invoke(self, ctx): try: return super().invoke(ctx) except UnknownConfigKeyError as exc: - raise click.ClickException(str(exc)) from exc + raise ConfigRejectedError(str(exc)) from exc @click.group(cls=ConfigAwareGroup) diff --git a/src/proteus/config/_atmos_clim.py b/src/proteus/config/_atmos_clim.py index dda84a5a8..fa403342d 100644 --- a/src/proteus/config/_atmos_clim.py +++ b/src/proteus/config/_atmos_clim.py @@ -363,6 +363,9 @@ class AtmosClim: Spectral file group defining gas opacities. See https://proteus-framework.org/SOCRATES/Reference/proteus_spectral_file_reference.html spectral_bands: str Number of wavenumber bands in k-table. + spectral_cache: str | None + Folder in which to reuse prepared spectral files across runs that share + a stellar spectrum. None disables the cache and every run builds its own. num_levels: int Number of vertical atmosphere levels. p_top: float @@ -408,6 +411,7 @@ class AtmosClim: # Grid and spectral setup (shared by agni + janus) spectral_group: str = field(default='Honeyside') spectral_bands: str = field(default='48') + spectral_cache: str | None = field(default=None, converter=none_if_none) num_levels: int = field(default=50, validator=ge(15)) p_top: float = field(default=1e-6, validator=gt(0)) p_obs: float = field(default=20e-3, validator=gt(0)) @@ -455,6 +459,7 @@ def surf_state_int(self) -> int: 'module', 'spectral_group', 'spectral_bands', + 'spectral_cache', 'num_levels', 'p_top', 'p_obs', diff --git a/src/proteus/inference/BO.py b/src/proteus/inference/BO.py index 3aef51f7c..e7535a122 100644 --- a/src/proteus/inference/BO.py +++ b/src/proteus/inference/BO.py @@ -77,12 +77,13 @@ def BO_step(D, B, f, k, acqf, lock, worker_id, x_in=None): with lock: X = D['X'] Y = D['Y'] - busys = list(B.values()) + # Select by key, not by position: a worker that has finished or + # stopped is absent from B, so the position of an entry in the + # values list does not identify the worker that owns it. + busys = [v for wid, v in B.items() if wid != worker_id] t_1_lock = time.perf_counter() - busys = torch.cat(busys, dim=0) - d = X.shape[-1] best = Y.max().item() @@ -122,10 +123,14 @@ def BO_step(D, B, f, k, acqf, lock, worker_id, x_in=None): t_1_ac = time.perf_counter() - mask = torch.ones(busys.size(0), dtype=torch.bool) - mask[worker_id] = False - b = busys[mask] - dist = torch.min(torch.cdist(b, x)).item() + # Distance to the nearest point another worker is currently evaluating. + # Undefined when no other worker is busy + if busys: + b = torch.cat(busys, dim=0) + dist = torch.min(torch.cdist(b, x)).item() + else: + b = torch.zeros((0, d), dtype=dtype) + dist = None if d == 1: plot_iter( diff --git a/src/proteus/inference/async_BO.py b/src/proteus/inference/async_BO.py index 989e97caf..524666972 100644 --- a/src/proteus/inference/async_BO.py +++ b/src/proteus/inference/async_BO.py @@ -28,6 +28,7 @@ from proteus.inference.BO import BO_step, init_locs from proteus.inference.utils import get_kernel, load_dataset_csv, save_dataset_csv from proteus.utils.coupler import get_proteus_directories +from proteus.utils.logs import attach_worker_logfile # Tensor dtype for all computations dtype = torch.double @@ -65,6 +66,19 @@ def checkpoint(D: dict, logs: list, Ts: list, output_dir: str) -> None: ) +def _parent_logfile() -> str | None: + """Path of the logfile the inference run's logger is writing, if it has one. + + Read in the parent, because a spawned worker has no logging configuration + of its own to read it from. Returning the handler's own path rather than + rebuilding it keeps the logfile named in one place only. + """ + for handler in logging.getLogger('fwl').handlers: + if isinstance(handler, logging.FileHandler): + return handler.baseFilename + return None + + def worker( process_fun, build_obj, @@ -79,6 +93,8 @@ def worker( worker_id: int, log_list, output_dir: str, + logpath: str | None = None, + log_level: int = logging.INFO, ) -> None: """Worker subprocess that performs asynchronous BO steps. @@ -103,6 +119,74 @@ def worker( - worker_id (int): Unique identifier of this worker. - log_list (Manager.list): Shared list to store per-eval log dicts. - output_dir (str): Output directory for the whole inference call (abspath). + - logpath (str | None): Inference run logfile to reopen when this process has no + logging configuration of its own. + - log_level (int): Numeric level to log at, read from the parent. + + Returns + ---------- + - None + """ + # A spawned worker inherits no logging configuration on MacOS. + # Reattach before any work starts, so that a failure in + # the very first iteration is still recorded in the logfile. + if logpath: + attach_worker_logfile(logpath, log_level) + + try: + _worker_loop( + process_fun, + build_obj, + D_shared, + B, + T, + T0, + x_init, + n_init, + lock, + max_len, + worker_id, + log_list, + output_dir, + ) + except BaseException: + # A worker that dies takes its traceback with it: multiprocessing + # prints it to the parent's stderr without consulting the logging + # configuration, so nothing reaches the logfile. Record it here. + log.exception(f'Worker {worker_id} stopped early and will run no further evaluations') + raise + finally: + # Release this worker's busy point. + try: + with lock: + B.pop(worker_id, None) + except Exception: + log.warning(f'Worker {worker_id} could not release its busy point') + + +def _worker_loop( + process_fun, + build_obj, + D_shared, + B, + T, + T0: float, + x_init: torch.Tensor, + n_init: int, + lock, + max_len: int, + worker_id: int, + log_list, + output_dir: str, +) -> None: + """Run BO iterations until the evaluation budget is reached. + + The body of `worker`, separated so that failure reporting and busy-point + release wrap every exit path. + + Parameters + ---------- + - See `worker`; arguments are forwarded unchanged. Returns ---------- @@ -206,7 +290,8 @@ def parallel_process( - ref_config (str): Path to reference config to pass to objective_builder. - observables (dict): Target observables (keys) and values. - parameters (dict): Parameters (keys) with bounds (values) for inference. - - failure_codes (list[int]): Additional PROTEUS exit codes to treat as failures. + - failure_codes (list[int]): PROTEUS status codes that complete normally but + that this run excludes from the fit. Returns ---------- @@ -264,6 +349,10 @@ def parallel_process( # Set up step constraint max_steps = max_len - (n_workers - 1) + # Read in the parent: a spawned worker has none of this to read from. + worker_logpath = _parent_logfile() + worker_log_level = logging.getLogger('fwl').level + # Spawn worker processes procs = [] for wid in range(n_workers): @@ -286,6 +375,8 @@ def parallel_process( wid, log_list, output_abspath, + worker_logpath, + worker_log_level, ), ) p.start() @@ -300,4 +391,33 @@ def parallel_process( logs = list(log_list) T_elapsed = [t - T0 for t in list(T)] + # A worker that dies mid-run leaves the run looking complete. Report. + died = [wid for wid, p in enumerate(procs) if p.exitcode != 0] + if died: + names = ', '.join(str(wid) for wid in died) + log.error( + f'{len(died)} of {n_workers} workers stopped before the evaluation budget ' + f'was reached (workers {names}). Their exit codes were ' + f'{[procs[wid].exitcode for wid in died]}.' + f' Results are based on {len(D_final["X"])} evaluations ' + f'rather than the {max_len} requested.' + ) + # Nothing was added to the initial sample, so there is no optimisation to + # report and the best-fit summary would describe the initial design alone. + if len(D_final['X']) <= n_init: + if died: + cause = ( + f'{len(died)} of {n_workers} workers stopped early; see the messages ' + 'above for the cause.' + ) + else: + # Every worker exited on its first budget check. + n_steps = max_len - n_init + cause = ( + f'No worker failed: the config asks for {n_steps} optimisation ' + f'step{"" if n_steps == 1 else "s"} across {n_workers} workers. ' + f'Raise n_steps to at least n_workers ({n_workers}).' + ) + raise RuntimeError('No optimisation steps completed. ' + cause) + return D_final, logs, T_elapsed diff --git a/src/proteus/inference/failures.py b/src/proteus/inference/failures.py new file mode 100644 index 000000000..125916d53 --- /dev/null +++ b/src/proteus/inference/failures.py @@ -0,0 +1,298 @@ +"""Recording and reporting failing inference evaluations, and reporting outcomes +excluded through `failure_codes`. +""" + +from __future__ import annotations + +import logging +from collections import Counter +from dataclasses import dataclass, field +from pathlib import Path + +import pandas as pd + +from proteus.utils.helper import STATUS_MISSING, CommentFromStatus + +log = logging.getLogger('fwl.' + __name__) + +# Whether a failed child run aborts the study, or is scored as a bad sample. +# Defaults to scoring. +ABORT_ON_FAILURE_ENV = 'PROTEUS_INFERENCE_ABORT_ON_FAILURE' + +# Suffix for the file holding whatever a child wrote to its console. +CHILD_CONSOLE_SUFFIX = '_console.log' + +# How an evaluation that failed is classified. A run that +# crashed, or stopped in an error state, did not produce a result at all. A run +# that completed normally but ended on a status listed in the study's +# `failure_codes` did produce a result, but the study does not fit against +# that outcome. Only the first is a fault. +CATEGORY_FAILURE = 'failure' +CATEGORY_EXCLUDED = 'excluded' + +# Table inside the study output holding one row per unscored evaluation. +# Appended by the workers as they fail and read back once at the end, so that +# the summary covers initial sampling and optimisation alike without the two +# paths having to share any state while they run. +FAILURE_CSV = 'failures.csv' + +# Fixed columns of that table, in order. The swept parameter values follow, one +# column each. The two paths are what the user opens after: +# the logfile for a run that got far enough to configure its logger, +# the console capture for one that did not. +_FAILURE_COLUMNS = ( + 'worker', + 'iter', + 'category', + 'status', + 'status_desc', + 'exit_code', + 'reason', + 'out_dir', + 'log_path', + 'console_path', +) + + +@dataclass(eq=False) +class ProteusRunFailure(RuntimeError): + """A single child PROTEUS run that did not produce a usable result. + + Carries everything needed to diagnose the run without opening the study + by hand: which evaluation it was, where its output landed, how it died, + what PROTEUS recorded in its status file, and the parameter values that + produced it. `category` separates a genuine fault from a run with an + excluded status. Both score the failure value, but only the first is + reported as something having gone wrong. + + Faults that would affect every evaluation (eg no `proteus` on PATH) + stay as ordinary exceptions so they abort the study instead of being + scored as a bad sample. + """ + + reason: str + worker: int + iter: int + out_dir: str + exit_code: int | None = None + status: int = STATUS_MISSING + log_path: str | None = None + console_path: str | None = None + parameters: dict = field(default_factory=dict) + category: str = CATEGORY_FAILURE + + @property + def status_desc(self) -> str: + """Human-readable form of the PROTEUS status code.""" + if self.status == STATUS_MISSING: + return 'no readable status file (died during start-up)' + return CommentFromStatus(self.status) + + def summary(self) -> str: + """Single-line description naming the outcome and where to look next.""" + verb = 'excluded' if self.category == CATEGORY_EXCLUDED else 'failed' + parts = [ + f'PROTEUS run {verb} for worker={self.worker} iter={self.iter}: {self.reason}', + f'status {self.status} ({self.status_desc})', + ] + # A zero exit code is the norm for every path except a crash, where it + # is the one number that says which signal or error ended the run. + if self.exit_code: + parts.append(f'exit code {self.exit_code}') + parts.append(f'output {self.out_dir}') + return '; '.join(parts) + + def report(self) -> str: + """The summary plus the detail that is too long to log on one line.""" + lines = [self.summary()] + if self.log_path: + lines.append(f' logfile = {self.log_path}') + # Named whether or not a logfile exists: a run that died before its + # logger was configured left nothing else behind to read. + if self.console_path: + lines.append(f' console = {self.console_path}') + if self.parameters: + pretty = ', '.join(f'{k}={v:g}' for k, v in sorted(self.parameters.items())) + lines.append(f' parameters = {pretty}') + return '\n'.join(lines) + + def __str__(self) -> str: + return self.report() + + def __reduce__(self): + # A failure raised inside a pool worker is pickled to be re-raised in + # the parent. BaseException.__reduce__ rebuilds from `self.args`, + # which a dataclass __init__ leaves empty, so the default would fail + # to reconstruct this class. Rebuild from the fields instead. + return ( + self.__class__, + ( + self.reason, + self.worker, + self.iter, + self.out_dir, + self.exit_code, + self.status, + self.log_path, + self.console_path, + self.parameters, + self.category, + ), + ) + + +def find_run_logfile(out_abs: Path | str) -> str | None: + """Return the newest PROTEUS logfile in a run's output folder, if any. + + PROTEUS captures uncaught exceptions into this file, so it usually holds + the traceback for a crashed run. It does not exist for a run that failed + before the logger was configured. + """ + logs = sorted(Path(out_abs).glob('proteus_*.log')) + return str(logs[-1]) if logs else None + + +def record_failure(study_abs: Path | str, failure: ProteusRunFailure) -> str | None: + """Append one row to the study's failure table. + + Workers are separate processes with no shared state, so each appends its + own row rather than handing the failure back to the parent. The first + worker to fail creates the file with its header through an exclusive + create, which exactly one caller can win, and every later row is a single + append. A row is one `write` call of well under a pipe buffer, which the + kernel adds whole, so no lock is needed on a local filesystem. + + Parameters + ---------- + - study_abs (Path | str): Absolute path to the study output folder. + - failure (ProteusRunFailure): The failure to record. + + Returns + ---------- + - str | None: Path written, or None if the row could not be written. + Recording is best-effort: a study must not be brought down by a fault in + its own bookkeeping, so the failure being reported still reaches the log. + """ + row = {key: getattr(failure, key) for key in _FAILURE_COLUMNS if key != 'status_desc'} + row['status_desc'] = failure.status_desc + row.update(failure.parameters) + ordered = {key: row[key] for key in (*_FAILURE_COLUMNS, *failure.parameters)} + + target = Path(study_abs) / FAILURE_CSV + line = _csv_row(ordered.values()) + try: + target.parent.mkdir(parents=True, exist_ok=True) + try: + with open(target, 'x') as f: + f.write(_csv_row(ordered.keys()) + line) + except FileExistsError: + with open(target, 'a') as f: + f.write(line) + except OSError as err: + log.warning( + f'Could not record the failure of worker={failure.worker} ' + f'iter={failure.iter}: {err}' + ) + return None + return str(target) + + +def _csv_row(values) -> str: + """Render one CSV line, quoting the fields that need it.""" + fields = [] + for value in values: + text = '' if value is None else str(value) + if any(c in text for c in ',"\n'): + text = '"' + text.replace('"', '""') + '"' + fields.append(text) + return ','.join(fields) + '\n' + + +def read_failure_records(study_abs: Path | str) -> list[dict]: + """Read back the failure table written during a study. + + Parameters + ---------- + - study_abs (Path | str): Absolute path to the study output folder. + + Returns + ---------- + - list[dict]: One entry per unscored evaluation, ordered by worker then + iteration. An unreadable table is reported and treated as empty rather + than aborting the summary it feeds. + """ + target = Path(study_abs) / FAILURE_CSV + if not target.is_file(): + return [] + try: + table = pd.read_csv(target) + except (OSError, pd.errors.ParserError, pd.errors.EmptyDataError) as err: + log.warning(f'Skipping unreadable failure table {target}: {err}') + return [] + table = table.sort_values(['worker', 'iter'], kind='stable') + # An absent exit code or logfile reads back as NaN, which would print as + # 'nan' in the summary and compare equal to nothing. + return table.astype(object).where(table.notna(), None).to_dict('records') + + +def summarise_failures(output: str, n_attempted: int) -> int: + """Report on the study's unscored evaluations. + + The breakdown by cause, and the per-run paths are reported together at the end + of the inference run. Runs that failed and runs that were excluded are counted apart. + + Parameters + ---------- + - output (str): Absolute path to the study output folder. + - n_attempted (int): Total evaluations attempted, initial samples included. + + Returns + ---------- + - int: Number of evaluations that carry the failure score. + """ + records = read_failure_records(output) + n_unscored = len(records) + + log.info('-----------------------------------') + if not n_unscored: + log.info(f'Unscored evaluations: none, all {n_attempted} evaluations were usable') + log.info('-----------------------------------') + return 0 + + # A record with no category describes a genuine fault + n_excluded = sum(1 for r in records if r.get('category') == CATEGORY_EXCLUDED) + n_failed = n_unscored - n_excluded + + # One statement of the counts, raised to a warning when a run genuinely + # produced nothing + frac = n_unscored / max(n_attempted, 1) + log.log( + logging.WARNING if n_failed else logging.INFO, + f'Unscored evaluations: {n_unscored} of {n_attempted} ' + f'({100 * frac:.1f}%, initial samples included) carry the failure score: ' + f'{n_failed} produced no usable result, {n_excluded} completed on an ' + 'excluded status.', + ) + + # Grouped by cause, and labelled so that an excluded outcome is not read as + # something having gone wrong in the run that reached it. + log.info(f'{"Cause":52s} | Count') + for (category, desc), count in Counter( + (r.get('category') or CATEGORY_FAILURE, r.get('status_desc') or 'unknown') + for r in records + ).most_common(): + label = f'{desc} [excluded]' if category == CATEGORY_EXCLUDED else str(desc) + log.info(f'{label:52s} {count}') + # A few concrete places to look. A run that died before configuring its logger + # has no logfile, and its console capture is then the only record of why it refused to start. + sample = [rec.get('log_path') or rec.get('console_path') for rec in records] + sample = [path for path in sample if path][:3] + if sample: + log.info(f'Logfiles ({len(sample)} of {n_unscored} shown):') + for log_path in sample: + log.info(f' {log_path}') + log.info(f'Full list: {Path(output) / FAILURE_CSV}') + + log.info('-----------------------------------') + + return n_unscored diff --git a/src/proteus/inference/gen_D_init.py b/src/proteus/inference/gen_D_init.py index 25d4b91c4..35866b379 100644 --- a/src/proteus/inference/gen_D_init.py +++ b/src/proteus/inference/gen_D_init.py @@ -226,7 +226,8 @@ def sample_from_bounds( - nsamp (int): Number of initial samples to evaluate. - seed (int): RNG seed for Halton sequence generation. - n_workers (int): Number of parallel workers to use for evaluation. - - failure_codes (list[int]): Additional PROTEUS exit codes to treat as failures. + - failure_codes (list[int]): PROTEUS status codes that complete normally but + that this study excludes from the fit. Returns ---------- diff --git a/src/proteus/inference/inference.py b/src/proteus/inference/inference.py index 7f0c5c017..550fbddac 100644 --- a/src/proteus/inference/inference.py +++ b/src/proteus/inference/inference.py @@ -7,7 +7,9 @@ from __future__ import annotations # system libraries +import copy import logging +import math import os import shutil import time @@ -17,13 +19,26 @@ import proteus.inference.plot as plotBO +# proteus libraries +from proteus.config import ( + UnknownConfigKeyError, + find_key_problems, + format_orphan_message, + read_config, + structure_config, +) + # bayesopt source files from proteus.inference.async_BO import checkpoint, parallel_process +from proteus.inference.failures import ABORT_ON_FAILURE_ENV, summarise_failures from proteus.inference.gen_D_init import create_init -from proteus.inference.objective import prot_builder, set_child_timeout +from proteus.inference.objective import ( + WORKER_CONFIG_OVERRIDES, + apply_nested_updates, + prot_builder, + set_child_timeout, +) from proteus.inference.utils import print_results, str_time - -# proteus libraries from proteus.utils.coupler import get_proteus_directories from proteus.utils.helper import safe_rm from proteus.utils.logs import setup_logger @@ -33,6 +48,120 @@ log = logging.getLogger('fwl.' + __name__) +# Stand-in for the per-run output folder when validating. Only the shape of the +# value matters here; the real path carries the worker and iteration indices. +_VALIDATION_OUT_PATH = 'workers/w_0/i_0' + + +def _reject_bad_config(raw: dict, label: str) -> None: + """Apply the PROTEUS config checks to a raw dict, naming its source in errors. + + Parameters + ---------- + - raw (dict): Raw TOML dict to check against the PROTEUS config schema. + - label (str): Source description quoted back in any error message. + + Returns + ---------- + - None + + Raises: + UnknownConfigKeyError: If the dict carries keys outside the schema. + ValueError: If a value fails schema validation. + """ + orphans, mistyped = find_key_problems(raw) + if orphans or mistyped: + raise UnknownConfigKeyError(format_orphan_message(orphans, label, mistyped)) + structure_config(raw, label) + + +def parameter_bounds(parameters: dict) -> dict[str, tuple[float, float]]: + """Return the swept-parameter ranges as ordered float pairs. + + Parameters + ---------- + - parameters (dict): Mapping of dot-separated config keys to [min, max]. + + Returns + ---------- + - dict[str, tuple[float, float]]: Same keys, bounds as (min, max) floats. + + Raises: + ValueError: If a range is not a pair of numbers, or does not increase. + """ + bounds: dict[str, tuple[float, float]] = {} + for key, value in parameters.items(): + numeric = ( + isinstance(value, (list, tuple)) + and len(value) == 2 + and all(isinstance(v, (int, float)) for v in value) + ) + if not numeric: + raise ValueError( + f"Bounds for inference parameter '{key}' must be a pair of numbers " + f'[min, max], got {value!r}' + ) + low, high = float(value[0]), float(value[1]) + # TOML admits `inf` and `nan`. An infinite bound passes the schema's + # own range checks and then makes every unnormalised sample infinite. + if not (math.isfinite(low) and math.isfinite(high)): + raise ValueError( + f"Bounds for inference parameter '{key}' must be finite, got {value!r}" + ) + if low >= high: + raise ValueError( + f"Bounds for inference parameter '{key}' must increase, got [{low:g}, {high:g}]" + ) + bounds[key] = (low, high) + return bounds + + +def validate_reference_config(ref_config: str, parameters: dict) -> None: + """Reject a reference config the workers could not run, before any run starts. + + The file is checked exactly as PROTEUS checks its own input, and then again + with every swept parameter set to each end of its range. A mistyped + parameter name shows up as an unrecognised key, and a bound outside what + the schema accepts shows up as a validation failure, both reported here + rather than as a worker crash part-way through the study. + + Only the two ends of the range are checked, with every parameter moved + together, so this is a screen rather than a proof. A range whose interior + holds an invalid combination still passes. Conversely, a schema rule that + couples two swept parameters can make one of the two variants invalid even + though most of the space is fine: sweeping both `params.dt.minimum` and + `params.dt.maximum` can put the minimum above the maximum at one end, and + the study is refused. Sweep one side of such a pair, or widen the other. + + Parameters + ---------- + - ref_config (str): Path to the reference PROTEUS config file. + - parameters (dict): Mapping of dot-separated config keys to [min, max]. + + Returns + ---------- + - None + + Raises: + UnknownConfigKeyError: If any variant carries keys outside the schema. + ValueError: If a bound is malformed, or a variant fails validation. + """ + bounds = parameter_bounds(parameters) + raw = read_config(ref_config) + + # The file as the user wrote it. + _reject_bad_config(raw, str(ref_config)) + + # The file as a worker will run it. Bounds are cast to float to match what + # the optimiser writes back into each worker's config. + for label, index in (('lower', 0), ('upper', 1)): + updates = {key: pair[index] for key, pair in bounds.items()} + updates.update(WORKER_CONFIG_OVERRIDES) + updates['params.out.path'] = _VALIDATION_OUT_PATH + candidate = apply_nested_updates(copy.deepcopy(raw), updates) + _reject_bad_config(candidate, f'{ref_config} (parameters at their {label} bounds)') + + # Entry point for inference scheme, providing infererence-config dict def run_inference(config): """Run the full asynchronous Bayesian inference workflow. @@ -53,6 +182,18 @@ def run_inference(config): # dictionary of directories dirs = get_proteus_directories(config['output']) + # Everything that can be rejected from the config alone is rejected here, + # because the next step empties the output folder and a study re-run after + # a typo would otherwise destroy the previous study's results. + if config['n_workers'] >= os.cpu_count(): + raise RuntimeError(f'Not enough CPU cores for {config["n_workers"]} workers') + + config['ref_config'] = os.path.join(dirs['proteus'], config['ref_config']) + if not os.path.isfile(config['ref_config']): + raise FileNotFoundError('Cannot find reference config: ' + config['ref_config']) + + validate_reference_config(config['ref_config'], config['parameters']) + # Create output directory safe_rm(dirs['output']) os.makedirs(dirs['output']) @@ -79,17 +220,15 @@ def run_inference(config): # plumbed to worker processes through the environment. set_child_timeout(config.get('child_timeout_s')) + # Whether a failed simulation stops the study or is scored as a poor + # sample. Defaults to scoring, because a sweep over a wide parameter box + # is expected to reach combinations the simulator cannot integrate. + os.environ[ABORT_ON_FAILURE_ENV] = '1' if config.get('abort_on_failure', False) else '0' + # Default for configs that pre-date this field config.setdefault('failure_codes', []) - # Ensure there are enough CPU cores for the specified number of workers - if config['n_workers'] >= os.cpu_count(): - raise RuntimeError(f'Not enough CPU cores for {config["n_workers"]} workers') - # Check path to reference config - config['ref_config'] = os.path.join(dirs['proteus'], config['ref_config']) log.info(f'Reference config: {config["ref_config"]}') - if not os.path.isfile(config['ref_config']): - raise FileNotFoundError('Cannot find reference config: ' + config['ref_config']) # Update ref_config path to point to a copy, in case user removes the original file copy_config = os.path.join(os.path.join(dirs['output'], 'ref_config.toml')) @@ -135,6 +274,12 @@ def run_inference(config): log.info(f'This took: {t_1 - t_0:.2f} seconds') log.info('-----------------------------------') + # Account for the simulations that did not produce a usable result. Runs + # before the best-fit summary, so the reader sees how much of the study was + # real before reading what it concluded, and so the breakdown is still + # reported when every evaluation failed and the summary refuses to print. + summarise_failures(dirs['output'], len(D_final['X'])) + # Print summary of true vs. simulated observables and inferred parameters best_config = print_results(D_final, logs, config, dirs['output'], n_init) diff --git a/src/proteus/inference/objective.py b/src/proteus/inference/objective.py index 7a7c57e1f..8a4d41f0f 100644 --- a/src/proteus/inference/objective.py +++ b/src/proteus/inference/objective.py @@ -11,9 +11,20 @@ import torch from numpy import log10 +from proteus.inference.failures import ( + ABORT_ON_FAILURE_ENV, + CATEGORY_EXCLUDED, + CATEGORY_FAILURE, + CHILD_CONSOLE_SUFFIX, + STATUS_MISSING, + ProteusRunFailure, + find_run_logfile, + record_failure, +) from proteus.inference.transforms import unnormalize_parameters from proteus.utils.constants import element_list, gas_list from proteus.utils.coupler import get_proteus_directories, variable_is_logarithmic +from proteus.utils.helper import ReadStatus dtype = torch.double EPS_CLIP = 1e-10 @@ -29,6 +40,43 @@ DEFAULT_CHILD_TIMEOUT_S = 6 * 3600.0 _CHILD_TIMEOUT_ENV = 'PROTEUS_INFERENCE_CHILD_TIMEOUT_S' +# Config entries every worker overwrites in the reference config, regardless of +# which parameters are being swept. Shared with the startup validation so the +# configuration that is checked is the configuration that is run. +WORKER_CONFIG_OVERRIDES = { + 'params.out.plot_mod': 'none', + 'params.out.logging': 'WARNING', + 'params.out.archive_mod': 0, +} + +# Folder inside the study output where workers reuse prepared spectral files. +SPECTRAL_CACHE_DIR = 'spectral_cache' + +# Config entries every run sets to the same thing, or to a value derived from +# the run index. Excluded from failure reports, which name the swept values. +_FIXED_PARAMETER_KEYS = set(WORKER_CONFIG_OVERRIDES) | { + 'params.out.path', + 'atmos_clim.spectral_cache', +} + + +def run_output_dir(output: str, worker: int, iter: int) -> tuple[Path, Path]: + """Return the output folder of a single evaluation, relative and absolute. + + Parameters + ---------- + - output (str): Study output folder, relative to the PROTEUS output root. + - worker (int): Worker identifier. Initial samples use -1. + - iter (int): Iteration identifier within that worker. + + Returns + ---------- + - tuple[Path, Path]: The path as the simulator config records it, and the + absolute path on disk. + """ + out_dir = Path(output) / 'workers' / f'w_{worker}' / f'i_{iter}' + return out_dir, Path(get_proteus_directories(str(out_dir))['output']) + def set_child_timeout(seconds: float | None = None) -> None: """Record the per-child PROTEUS timeout for inference worker processes. @@ -58,6 +106,34 @@ def child_timeout_s() -> float | None: return val if val > 0 else None +def apply_nested_updates(config: dict, updates: dict) -> dict: + """Set dot-separated keys in a nested config dict, in place. + + Parameters + ---------- + - config (dict): Nested configuration dictionary, modified in place. + - updates (dict): Mapping of dot-separated key paths to new values. + + Returns + ---------- + - dict: The same dictionary that was passed in. + + Raises: + ValueError: If a key path descends through an entry that holds a value + rather than a table. + """ + for key, value in updates.items(): + parts = key.split('.') + d = config + for i, part in enumerate(parts[:-1]): + d = d.setdefault(part, {}) + if not isinstance(d, dict): + prefix = '.'.join(parts[: i + 1]) + raise ValueError(f"Cannot set '{key}': '{prefix}' holds a value, not a section") + d[parts[-1]] = value + return config + + def update_toml(config_file: str, updates: dict, output_file: str) -> None: """Update values in a TOML configuration file. @@ -83,12 +159,7 @@ def update_toml(config_file: str, updates: dict, output_file: str) -> None: config = toml.load(f) # Apply nested updates - for key, value in updates.items(): - parts = key.split('.') - d = config - for part in parts[:-1]: - d = d.setdefault(part, {}) - d[parts[-1]] = value + apply_nested_updates(config, updates) # Ensure destination directory exists output_path.parent.mkdir(parents=True, exist_ok=True) @@ -122,13 +193,19 @@ def run_proteus( ---------- - observables_dict (dict): Mapping of observable names to their simulated values. - status (int): Status code indicating the outcome of the simulation. + + Raises: + ProteusRunFailure: If this particular run did not produce a usable + result. Carries the status code, the path to the run's logfile and + the parameters that produced it. + RuntimeError: If the `proteus` command itself cannot be executed, which + would affect every run rather than this one. + KeyError: If a requested observable is absent from the output, which + likewise applies to every run. """ # Construct run-specific paths - run_id = Path('workers') / f'w_{worker}' / f'i_{iter}' - out_dir = Path(output) / run_id - - out_abs = Path(get_proteus_directories(str(out_dir))['output']) + out_dir, out_abs = run_output_dir(output, worker, iter) out_cfg = out_abs / 'input.toml' out_csv = out_abs / 'runtime_helpfile.csv' @@ -138,9 +215,15 @@ def run_proteus( # Inject output path into simulation parameters parameters['params.out.path'] = str(out_dir) + # Every evaluation of an inference run that holds the star fixed builds the same + # prepared spectral file. Point them all at one folder so only the first + # pays for it. + parameters['atmos_clim.spectral_cache'] = str( + Path(get_proteus_directories(output)['output']) / SPECTRAL_CACHE_DIR + ) + # Don't allow workers to make plots or logs - parameters['params.out.plot_mod'] = 'none' - parameters['params.out.logging'] = 'WARNING' + parameters.update(WORKER_CONFIG_OVERRIDES) # Generate config update_toml(ref_config, parameters, str(out_cfg)) @@ -149,48 +232,85 @@ def run_proteus( env = dict(**os.environ) env['OMP_NUM_THREADS'] = '1' - # Run PROTEUS + # Swept parameter values only, for the failure report. The output path and + # the worker overrides are fixed for every run and add no diagnostic value. + swept = {k: v for k, v in parameters.items() if k not in _FIXED_PARAMETER_KEYS} + + # A run that dies before its logger is configured leaves no logfile behind, so + # this stream records it. + console = out_abs.parent / f'{out_abs.name}{CHILD_CONSOLE_SUFFIX}' + + def _failure(reason: str, exit_code: int | None) -> ProteusRunFailure: + """Assemble a failure report for this run. + + The status file is read here rather than at the point of the raise so + that a crashed run is described by what PROTEUS recorded about itself, + not only by its exit code. + """ + return ProteusRunFailure( + reason=reason, + worker=worker, + iter=iter, + out_dir=str(out_abs), + exit_code=exit_code, + status=ReadStatus(out_abs), + log_path=find_run_logfile(out_abs), + console_path=str(console), + parameters=swept, + ) + command = ['proteus', 'start', '-c', str(out_cfg), '--offline'] + console.parent.mkdir(parents=True, exist_ok=True) + # Opened outside the try so that a failure to create it is not mistaken + # for the simulator being absent. + stream = open(console, 'w') try: subprocess.run( command, check=True, text=True, env=env, - stdout=subprocess.DEVNULL, + stdout=stream, stderr=subprocess.STDOUT, timeout=child_timeout_s(), ) except FileNotFoundError as err: + # Applies to every run, not just this one, so it is not a sample that + # can be scored badly and skipped. log.error(f"Cannot execute '{command[0]}': command not found") raise RuntimeError("Failed to run PROTEUS: 'proteus' command not found") from err except subprocess.TimeoutExpired as err: - log.error( - f'PROTEUS run exceeded the {child_timeout_s()} s timeout for ' - f'worker={worker} iter={iter} outdir={str(out_dir)}' - ) - raise RuntimeError( - f'PROTEUS run timed out after {child_timeout_s()} s for worker={worker} iter={iter}' - ) from err + timeout = child_timeout_s() + raise _failure(f'exceeded the {timeout} s timeout', exit_code=None) from err except subprocess.CalledProcessError as err: - log.error(f'PROTEUS run failed for worker={worker} iter={iter} outdir={str(out_dir)}') - raise RuntimeError( - f'Failed to run PROTEUS for worker={worker} iter={iter}; exit code {err.returncode}' - ) from err + raise _failure('the simulator exited with an error', exit_code=err.returncode) from err + finally: + stream.close() # Re-write config in case simulator mutates or removes it update_toml(ref_config, parameters, str(out_cfg)) # Read status file - status = 20 # default to Generic Error - try: - with open(out_abs / 'status', 'r') as f: - status = int(f.readlines()[0].strip()) - except Exception as e: - log.warning(f'Failed to read status file for worker={worker} iter={iter}: {e}') + status = ReadStatus(out_abs) - # Read simulator output - df_row = dict(pd.read_csv(out_csv, delimiter=r'\s+').iloc[-1]) + # Read simulator output. A run that exits cleanly but writes no usable + # helpfile (killed mid-write, or stopped before the first row) is a failed + # sample, not a crash of the study. + try: + df_row = dict(pd.read_csv(out_csv, delimiter=r'\s+').iloc[-1]) + except ( + FileNotFoundError, + OSError, + pd.errors.EmptyDataError, + pd.errors.ParserError, + IndexError, + ) as err: + # A truncated whitespace-delimited file usually presents as a ragged + # row (ParserError) rather than an empty one, so both are caught. + raise _failure( + f'exited cleanly but produced no readable output ({out_csv.name})', + exit_code=0, + ) from err # Handle case where atmosphere has escaped # Set VMRs and MMW to zero @@ -293,7 +413,8 @@ def J( - iter (int): Iteration number. - output (str): Path to output folder relative to PROTEUS output folder. - ref_config (str): Reference TOML config path. - - failure_codes (list[int]): Additional PROTEUS exit codes to treat as failures. + - failure_codes (list[int]): PROTEUS status codes that complete normally but + that this study excludes from the fit. Returns ---------- @@ -302,17 +423,79 @@ def J( # Map normalized x to raw parameter dict and run PROTEUS raw = {parameters[i]: x[0, i].item() for i in range(len(parameters))} - sim_vals, sim_status = run_proteus( - parameters=raw, - worker=worker, - iter=iter, - observables=list(true_observables.keys()), - ref_config=ref_config, - output=output, - ) + try: + sim_vals, sim_status = run_proteus( + parameters=raw, + worker=worker, + iter=iter, + observables=list(true_observables.keys()), + ref_config=ref_config, + output=output, + ) + except ProteusRunFailure as failure: + # A parameter combination the simulator cannot integrate is an + # expected outcome of sweeping a wide box, so it is scored as a poor + # sample and the study continues. Every such run is reported once, + # and the full report goes to the failure record. + # Recorded before the abort check, so an aborted study still leaves + # the record of what stopped it. + record_failure(get_proteus_directories(output)['output'], failure) + if os.environ.get(ABORT_ON_FAILURE_ENV, '0') == '1': + raise + log.warning(failure.summary()) + log.debug(failure.report()) + return BAD_OBJ_VALUE * torch.ones((1, 1), dtype=dtype) - # If status indicates failure, return very bad objective value - if (20 <= sim_status <= 29) or (sim_status in [0, 1]) or (sim_status in failure_codes): + # Runs that exit cleanly but stop in an error state, such as a run halted + # through its keepalive file (status 25), or that never reach the main loop + # (status 0 and 1). An unreadable status counts here too: the run's own + # account of itself is missing, so its output cannot be trusted. + failed = (20 <= sim_status <= 28) or (sim_status in (0, 1, STATUS_MISSING)) + + # Runs that completed normally on an outcome this study does not fit + # against, named by the `failure_codes` field of the inference config: a + # run stopped by its clock limit (status 11) or one whose volatiles all + # escaped (status 15), for instance. Nothing went wrong in such a run, so + # it is scored as a poor sample but is not reported as a fault. + excluded = (not failed) and (sim_status in failure_codes) + + # Either way the evaluation carries the failure score instead of a fit + # quality, and is recorded so that the end-of-study tally covers it. + if failed or excluded: + _, out_abs = run_output_dir(output, worker, iter) + # Built once, so the entry left on disk and the exception raised under + # `abort_on_failure` describe the same run. + failure = ProteusRunFailure( + reason=( + 'exited cleanly but stopped in a failure state' + if failed + else 'completed on a status this study excludes' + ), + worker=worker, + iter=iter, + out_dir=str(out_abs), + exit_code=0, + status=sim_status, + log_path=find_run_logfile(out_abs), + parameters=raw, + category=CATEGORY_FAILURE if failed else CATEGORY_EXCLUDED, + ) + # Recorded before the abort check, so an aborted study still leaves + # the record of what stopped it. + record_failure(get_proteus_directories(output)['output'], failure) + if failed: + # A clean exit on an error status is as much a fault as a crash, + # so it honours `abort_on_failure` the same way. An excluded + # outcome never does: nothing went wrong in such a run. + if os.environ.get(ABORT_ON_FAILURE_ENV, '0') == '1': + raise failure + log.warning(failure.summary()) + else: + # Nothing went wrong in such a run, so it is reported at info + # level and, like a fault, on one line. + log.info(failure.summary()) + # The rest of the report is kept out of the study log + log.debug(failure.report()) return BAD_OBJ_VALUE * torch.ones((1, 1), dtype=dtype) # Compute value of objective function given these results @@ -340,7 +523,8 @@ def prot_builder( - iter (int): Iteration number (seed) for reproducibility. - output (str): Path to output folder relative to PROTEUS output folder. - ref_config (str): Reference TOML config path. - - failure_codes (list[int]): Additional PROTEUS exit codes to treat as failures. + - failure_codes (list[int]): PROTEUS status codes that complete normally but + that this study excludes from the fit. Returns ---------- diff --git a/src/proteus/inference/plot.py b/src/proteus/inference/plot.py index 4a742cb71..bf6418e17 100644 --- a/src/proteus/inference/plot.py +++ b/src/proteus/inference/plot.py @@ -562,8 +562,10 @@ def plot_result_correlation(pars: dict, obs: dict, directory): par_keys = list(pars.keys()) obs_keys = list(obs.keys()) - # Get directories for all cases of interest - cases = sorted((Path(directory) / 'workers').glob('w_*/i_*')) + # Get directories for all cases of interest. Filtered to directories only: + # a worker's `_console.log` capture file (or any other stray sibling) also + # matches the `i_*` glob but is not a case directory. + cases = sorted(p for p in (Path(directory) / 'workers').glob('w_*/i_*') if p.is_dir()) # Extract parameters and observables X, Y = [], [] diff --git a/src/proteus/inference/utils.py b/src/proteus/inference/utils.py index 872c83f7d..bb6f843a3 100644 --- a/src/proteus/inference/utils.py +++ b/src/proteus/inference/utils.py @@ -32,7 +32,7 @@ from gpytorch.kernels import MaternKernel, RBFKernel from gpytorch.priors.torch_priors import LogNormalPrior -from proteus.inference.objective import EPS_CLIP, eval_obj +from proteus.inference.objective import BAD_OBJ_VALUE, EPS_CLIP, eval_obj from proteus.inference.transforms import unnormalize_parameters from proteus.utils.constants import gas_list @@ -172,8 +172,33 @@ def print_results(D, logs, config, output, n_init): X = D['X'] Y = D['Y'] + # Count the evaluations that were never scored on fit quality, so a study + # built mostly on those is not read as a converged result. Such a run + # scores BAD_OBJ_VALUE, whether it failed outright or completed on a + # status the study excludes; the objective value alone cannot tell the two + # apart, so the wording here covers both and the tally above splits them. + optim_Y = Y[n_init:] + n_optim = len(optim_Y) + n_unscored = int((optim_Y == BAD_OBJ_VALUE).sum().item()) + if n_unscored: + log.warning( + f'{n_unscored} of {n_optim} optimisation evaluations carry the failure ' + 'score rather than a fit quality, because they failed or completed on an ' + 'excluded status; the per-run reports above name each one.' + ) + + # No evaluation was scored, so the best of them is still a run with no fit + # to report. Say so rather than failing later on its missing helpfile. + if n_optim and n_unscored == n_optim: + raise RuntimeError( + f'None of the {n_optim} optimisation evaluations produced a fit quality, ' + 'so there is no best fit to report. The per-run reports above name the ' + 'cause of each; the most common causes are a parameter range that leaves the model unphysical, ' + 'and a `failure_codes` list that excludes the outcome most runs reach.' + ) + # Find best index, ignoring the initial points - i_opt: int = Y[n_init:].argmax() + n_init + i_opt: int = optim_Y.argmax() + n_init log_opt = logs[i_opt] J_opt: float = Y[i_opt].item() diff --git a/src/proteus/utils/helper.py b/src/proteus/utils/helper.py index 9b1db92ca..ee0683641 100644 --- a/src/proteus/utils/helper.py +++ b/src/proteus/utils/helper.py @@ -355,6 +355,36 @@ def UpdateStatusfile(dirs: dict, status: int): hdl.write('%s\n' % desc) +# Status written by PROTEUS before its output folder is cleaned, and never +# rewritten until the main loop starts. A child that dies in between leaves no +# status file at all, so a missing file is reported as such rather than being +# silently reported as a generic error. The value sits outside the range of +# every status PROTEUS writes, so "wrote status 0 (Started) then died" stays +# distinguishable from "never wrote one". +STATUS_MISSING = -1 + + +def ReadStatus(out_abs: Path | str) -> int: + """Read the PROTEUS status code from a finished run's output folder. + + Parameters + ---------- + - out_abs (Path | str): Absolute path to the run's output folder. + + Returns + ---------- + - int: The status code, or `STATUS_MISSING` when no readable status file + exists. A missing file is itself diagnostic: PROTEUS deletes the status + it writes at start-up when it cleans the output folder, and does not + write another until the main loop begins. + """ + try: + with open(Path(out_abs) / 'status', 'r') as f: + return int(f.readlines()[0].strip()) + except Exception: + return STATUS_MISSING + + def CleanDir(directory, keep_stdlog=False): """Clean a directory. diff --git a/src/proteus/utils/logs.py b/src/proteus/utils/logs.py index f427e57ef..0e0795c9e 100644 --- a/src/proteus/utils/logs.py +++ b/src/proteus/utils/logs.py @@ -207,6 +207,51 @@ def bootstrap_logger(level: str = 'INFO'): return custom_logger +def attach_worker_logfile(logpath: str, level_code: int = logging.INFO): + """Attach an appending file handler to the 'fwl' logger if it has none. + + A worker process started with the 'spawn' method (default on macOS) + re-imports the package instead of inheriting the parent's logging + configuration. Records it emits then find no handler and fall through to + ``logging.lastResort``, which writes to stderr, so nothing the worker + reports reaches the study logfile, including the traceback of a worker + that dies. Under 'fork', the parent's handlers are inherited already + and this is a no-op. + + The file is opened in append mode, where ``setup_logger`` recreates it: + the parent owns the logfile, and a worker must add to it rather than + truncate the record of the run so far. + + Parameters + ---------- + logpath : str + Path of the logfile the parent's logger is already writing. + level_code : int + Numeric log level, read from the parent's logger before the worker + starts, so the worker honours the level the study was run at. + + Returns + ------- + logging.Logger + The 'fwl' logger. + """ + custom_logger = logging.getLogger('fwl') + + # Do not touch an already-configured logger. Under 'fork' this process + # inherited the parent's handlers, and adding a second one would write + # every worker line to the logfile twice. + if custom_logger.handlers: + return custom_logger + + fh = logging.FileHandler(logpath, mode='a') + fh.setFormatter(logging.Formatter('[ %(levelname)-5s ] %(message)s')) + fh.setLevel(level_code) + custom_logger.addHandler(fh) + custom_logger.setLevel(level_code) + + return custom_logger + + def GetCurrentLogfileIndex(output_dir: str): """ Get the index of the current logfile, returning -1 if none exists diff --git a/tests/atmos_clim/test_agni.py b/tests/atmos_clim/test_agni.py index 4f68bb933..cb431d2b7 100644 --- a/tests/atmos_clim/test_agni.py +++ b/tests/atmos_clim/test_agni.py @@ -5,6 +5,9 @@ - Aerosol discovery (_determine_aerosols) - Condensate species determination (_determine_condensates) - AGNI atmosphere initialization (init_agni_atmos) +- Reuse of prepared spectral files across runs, covering the folder AGNI builds + them in, the hit path that skips the stellar insertion, and the contract that + an unusable cache slows a run down without changing its result - Temperature-profile carry-over between iterations (_validate_stored_profile, update_agni_atmos), covering pressure and temperature positivity, profile monotonicity under interpolation, and the atmosphere-failure contract when @@ -18,6 +21,7 @@ from __future__ import annotations import logging +from pathlib import Path from types import SimpleNamespace from unittest.mock import MagicMock, patch @@ -33,6 +37,7 @@ init_agni_atmos, write_atmos_ncdf, ) +from proteus.atmos_clim.spectral_cache import cache_key from proteus.utils.constants import noble_gases pytestmark = [pytest.mark.unit, pytest.mark.timeout(30)] @@ -417,6 +422,193 @@ def test_init_agni_atmos_greygas_bypasses_spectral_copy(monkeypatch, tmp_path): assert fake_agni.last_setup_kwargs['κ_grey_sw'] == pytest.approx(0.2) +class _SpectralWritingAGNI(_FakeAGNI): + """Fake AGNI that writes the runtime spectral pair where the real one does. + + AGNI builds `/runtime.sf` and its `_k` companion inside `allocate!`, + and only when a stellar spectrum is supplied; an empty spectrum means the + spectral file it was handed is already prepared and is used untouched. + """ + + def _allocate_b(self, atmos, input_star, **kwargs): + if input_star: + io_dir = Path(self.last_setup_kwargs['IO_DIR']) + io_dir.mkdir(parents=True, exist_ok=True) + star_name = Path(input_star).name + (io_dir / 'runtime.sf').write_text(f'prepared from {star_name}', encoding='utf-8') + (io_dir / 'runtime.sf_k').write_text(f'ktable from {star_name}', encoding='utf-8') + return super()._allocate_b(atmos, input_star, **kwargs) + + +def _setup_cached_spectral_run(monkeypatch, tmp_path, cache_dir, verbosity=1, log_level='INFO'): + """Wire up an init_agni_atmos call that goes through the spectral-file cache. + + The base spectral file and the stellar spectrum are real files, because the + cache key fingerprints both. `verbosity` and `log_level` select which folder + AGNI works in: the output folder only when verbose or debug-logged. + """ + fake_agni = _SpectralWritingAGNI() + fake_jl = SimpleNamespace(AGNI=fake_agni, Dict=dict, Char=str) + + output_dir = tmp_path / 'out' + data_dir = output_dir / 'data' + data_dir.mkdir(parents=True) + sflux = data_dir / '100.sflux' + sflux.write_text('400.0 1.0\n500.0 2.0\n', encoding='utf-8') + + fwl_dir = tmp_path / 'fwl' + fwl_dir.mkdir(parents=True, exist_ok=True) + base_sf = fwl_dir / 'Honeyside.sf' + base_sf.write_text('base spectral file, no star inserted', encoding='utf-8') + + scratch = tmp_path / 'scratch' + + def _fake_tmp_folder(): + scratch.mkdir(parents=True, exist_ok=True) + return str(scratch) + + config = _build_greygas_config() + config.atmos_clim.agni.spectral_file = None + config.atmos_clim.agni.verbosity = verbosity + config.atmos_clim.spectral_group = 'Honeyside' + config.atmos_clim.spectral_bands = '16' + config.atmos_clim.spectral_cache = str(cache_dir) + config.params.out.logging = log_level + + monkeypatch.setattr(agni_mod, 'jl', fake_jl) + monkeypatch.setattr(agni_mod, 'convert', lambda _typ, value: value) + monkeypatch.setattr(agni_mod, '_construct_voldict', lambda *_a, **_k: {'H2O': 1.0}) + monkeypatch.setattr(agni_mod, 'sync_log_files', lambda *_a, **_k: None) + monkeypatch.setattr(agni_mod, 'get_spfile_path', lambda *_a, **_k: str(base_sf)) + monkeypatch.setattr(agni_mod, 'create_tmp_folder', _fake_tmp_folder) + + return SimpleNamespace( + fake_agni=fake_agni, + dirs={'output': str(output_dir), 'agni': '/fake/agni', 'fwl': str(fwl_dir)}, + config=config, + hf_row={ + 'F_ins': 1000.0, + 'albedo_pl': 0.2, + 'T_surf': 900.0, + 'gravity': 9.8, + 'R_int': 6.4e6, + 'P_surf': 1.0, + 'axial_period': 86400.0, + 'longitude': 0.0, + 'latitude': 0.0, + }, + output_dir=output_dir, + scratch=scratch, + base_sf=base_sf, + sflux=sflux, + ) + + +@pytest.mark.unit +@pytest.mark.parametrize( + ('verbosity', 'log_level', 'work_dir'), + [(1, 'INFO', 'scratch'), (2, 'INFO', 'output')], + ids=['quiet-run-works-in-scratch', 'verbose-run-works-in-output'], +) +def test_spectral_cache_is_filled_from_the_folder_agni_wrote_in( + monkeypatch, tmp_path, verbosity, log_level, work_dir +): + """A run that builds a spectral file leaves a cache entry, in either work folder. + + AGNI writes the prepared file into its own working folder, which is the run's + output folder only when the run is verbose or debug-logged. A quiet run, the + default and the one inference workers use, works in a scratch folder instead; + harvesting the entry from the output folder there stores nothing at all, so + the cache stays empty and every later run repeats the insertion. + """ + cache = tmp_path / 'cache' + ctx = _setup_cached_spectral_run( + monkeypatch, tmp_path, cache, verbosity=verbosity, log_level=log_level + ) + + atmos = init_agni_atmos(ctx.dirs, ctx.config, ctx.hf_row) + assert atmos is not None + + # Cache miss: this run did the insertion itself, so allocate saw the spectrum. + assert ctx.fake_agni.last_allocate_input_star == str(ctx.sflux) + + built_in = ctx.scratch if work_dir == 'scratch' else ctx.output_dir + assert (built_in / 'runtime.sf').is_file() + + key = cache_key(ctx.base_sf, ctx.sflux, 'Honeyside', '16') + assert sorted(p.name for p in cache.iterdir()) == [f'{key}.sf', f'{key}.sf_k'] + assert (cache / f'{key}.sf').read_text() == (built_in / 'runtime.sf').read_text() + assert (cache / f'{key}.sf_k').read_text() == (built_in / 'runtime.sf_k').read_text() + + # Discriminating guard: in the quiet run the output folder holds no prepared + # file, so a harvest pointed there would find nothing and cache nothing. + quiet_output_is_empty = not (ctx.output_dir / 'runtime.sf').is_file() + assert quiet_output_is_empty == (work_dir == 'scratch') + + +@pytest.mark.unit +def test_a_cached_spectral_file_is_reused_without_reinserting_the_spectrum( + monkeypatch, tmp_path +): + """A cache hit hands AGNI the prepared file and skips the stellar insertion. + + The seeded pair has to land in the folder AGNI reads from, and the path + handed to setup has to be that copy: pointing at the output folder in a quiet + run names a file that was never created there. + """ + cache = tmp_path / 'cache' + cache.mkdir() + ctx = _setup_cached_spectral_run(monkeypatch, tmp_path, cache) + + key = cache_key(ctx.base_sf, ctx.sflux, 'Honeyside', '16') + (cache / f'{key}.sf').write_text('cached prepared file', encoding='utf-8') + (cache / f'{key}.sf_k').write_text('cached ktable', encoding='utf-8') + + atmos = init_agni_atmos(ctx.dirs, ctx.config, ctx.hf_row) + assert atmos is not None + + # Empty spectrum: AGNI takes the file as already prepared and does not rebuild. + assert ctx.fake_agni.last_allocate_input_star == '' + + # setup_b positional args: [dirs['agni'], dirs['output'], input_sf, ...] + assert ctx.fake_agni.last_setup_args[2] == str(ctx.scratch / 'runtime.sf') + assert (ctx.scratch / 'runtime.sf').read_text() == 'cached prepared file' + assert (ctx.scratch / 'runtime.sf_k').read_text() == 'cached ktable' + + # Guard: the companion must travel with its file. A seeded pair that AGNI + # cannot find is the failure mode the path-choice above exists to avoid. + assert not (ctx.output_dir / 'runtime.sf').exists() + + +@pytest.mark.unit +def test_a_cache_that_cannot_be_written_costs_time_and_not_correctness( + monkeypatch, tmp_path, caplog +): + """An unusable cache folder degrades to a normal build instead of failing. + + A cache path occupied by a regular file cannot hold entries. The run must + still initialise, still insert the spectrum itself, and leave the occupying + file untouched. + """ + blocked = tmp_path / 'blocked' + blocked.write_text('not a folder', encoding='utf-8') + ctx = _setup_cached_spectral_run(monkeypatch, tmp_path, blocked) + + with caplog.at_level(logging.WARNING, logger='fwl.proteus.atmos_clim.spectral_cache'): + atmos = init_agni_atmos(ctx.dirs, ctx.config, ctx.hf_row) + + assert atmos is not None + assert 'Could not store spectral file in cache' in caplog.text + + # The run built its own file, exactly as it would with the cache switched off. + assert ctx.fake_agni.last_allocate_input_star == str(ctx.sflux) + assert (ctx.scratch / 'runtime.sf').is_file() + + # Nothing was written over the occupying file. + assert blocked.is_file() + assert blocked.read_text() == 'not a folder' + + @pytest.mark.unit def test_init_agni_atmos_loads_the_row_matched_profile(monkeypatch, tmp_path): """init_agni_atmos seeds AGNI from the atmosphere written for this row. diff --git a/tests/atmos_clim/test_spectral_cache.py b/tests/atmos_clim/test_spectral_cache.py new file mode 100644 index 000000000..27c1e3d5a --- /dev/null +++ b/tests/atmos_clim/test_spectral_cache.py @@ -0,0 +1,212 @@ +""" +Unit tests for reuse of prepared spectral files across runs. + +Covers `proteus.atmos_clim.spectral_cache`: what makes two runs share a +prepared file, that the pair is seeded and stored together, and that a cache +which cannot be read or written costs a run time rather than correctness. + +References: + - docs/How-to/testing.md + - docs/Explanations/test_framework.md +""" + +from __future__ import annotations + +import pytest + +from proteus.atmos_clim.spectral_cache import ( + SPECTRAL_SUFFIXES, + cache_key, + seed_from_cache, + store_in_cache, +) + +pytestmark = [pytest.mark.unit, pytest.mark.timeout(30)] + + +def _make_inputs(tmp_path, star_bytes=b'1.0 2.0\n3.0 4.0\n'): + """Write a base spectral file and a stellar spectrum, and return both.""" + base = tmp_path / 'Honeyside.sf' + base.write_bytes(b'x' * 4096) + star = tmp_path / '0.sflux' + star.write_bytes(star_bytes) + return base, star + + +def _make_prepared(out_dir, marker=b'prepared'): + """Write the prepared pair a finished build leaves in an output folder.""" + out_dir.mkdir(parents=True, exist_ok=True) + for suffix in SPECTRAL_SUFFIXES: + (out_dir / f'runtime.sf{suffix}').write_bytes(marker + suffix.encode()) + + +@pytest.mark.unit +def test_key_tracks_the_stellar_spectrum_and_the_spectral_resolution(tmp_path): + """Two runs share a prepared file only when every input that goes into + building it agrees. The stellar spectrum is hashed by content, so a sweep + over any star parameter changes the key without this module having to know + which config fields those are. + """ + base, star = _make_inputs(tmp_path) + key = cache_key(base, star, 'Honeyside', '48') + + # Same inputs, same entry: this is what lets a study reuse one build. + assert cache_key(base, star, 'Honeyside', '48') == key + + # A different stellar spectrum is a different file, even byte-for-byte the + # same length, so a content hash rather than a size check is required. + other_star = tmp_path / 'other.sflux' + other_star.write_bytes(b'9.0 2.0\n3.0 4.0\n') + assert other_star.stat().st_size == star.stat().st_size + assert cache_key(base, other_star, 'Honeyside', '48') != key + + # Resolution and group select a different base file, so neither may collide. + assert cache_key(base, star, 'Honeyside', '256') != key + assert cache_key(base, star, 'Frostflow', '48') != key + + +@pytest.mark.unit +def test_key_changes_when_the_base_spectral_file_is_updated(tmp_path): + """A FWL_DATA update must not be served a stale entry. The base file is + fingerprinted by size and modification time rather than hashed, because it + is large and read-only, so both are exercised here. + """ + base, star = _make_inputs(tmp_path) + key = cache_key(base, star, 'Honeyside', '48') + + # Same size, newer file: the mtime component has to carry this one. + stat = base.stat() + base.write_bytes(b'y' * 4096) + import os + + os.utime(base, (stat.st_atime, stat.st_mtime + 120)) + assert base.stat().st_size == 4096 + key_touched = cache_key(base, star, 'Honeyside', '48') + assert key_touched != key + + # Same mtime, different size: the size component has to carry this one. + base.write_bytes(b'y' * 8192) + os.utime(base, (stat.st_atime, stat.st_mtime + 120)) + assert cache_key(base, star, 'Honeyside', '48') != key_touched + + +@pytest.mark.unit +def test_a_stored_entry_is_seeded_back_for_a_later_run(tmp_path): + """The round trip a study relies on: the first run stores what it built and + every later run with the same inputs starts from it. Both files of the pair + travel together, because the module that consumes them checks only the + first and would otherwise run with a missing companion. + """ + cache = tmp_path / 'cache' + first = tmp_path / 'run_0' + _make_prepared(first) + + assert store_in_cache(cache, 'abc123', first) is True + + second = tmp_path / 'run_1' + assert seed_from_cache(cache, 'abc123', second) is True + for suffix in SPECTRAL_SUFFIXES: + seeded = second / f'runtime.sf{suffix}' + assert seeded.is_file() + assert seeded.read_bytes() == (first / f'runtime.sf{suffix}').read_bytes() + + # Discrimination: a key nothing was stored under is a miss, so the run + # builds its own file rather than silently reusing another star's. + third = tmp_path / 'run_2' + assert seed_from_cache(cache, 'def456', third) is False + assert not (third / 'runtime.sf').exists() + + +@pytest.mark.unit +def test_a_half_written_entry_is_not_served(tmp_path): + """An entry is usable only once both files are in place. A reader that + accepted the first alone would hand a run a prepared file whose companion + is missing, which is worse than a miss because the run would not rebuild. + """ + cache = tmp_path / 'cache' + cache.mkdir() + # Only the first of the pair, as a reader would see mid-store. + (cache / 'abc123.sf').write_bytes(b'prepared') + + out = tmp_path / 'run' + assert seed_from_cache(cache, 'abc123', out) is False + assert not (out / 'runtime.sf').exists() + + # Discrimination: completing the pair makes the same key usable, so the + # refusal above came from the missing companion and not from the reader + # rejecting every entry. + (cache / 'abc123.sf_k').write_bytes(b'prepared_k') + assert seed_from_cache(cache, 'abc123', out) is True + assert (out / 'runtime.sf').is_file() + + +@pytest.mark.unit +def test_a_run_that_built_nothing_stores_nothing(tmp_path): + """Storing is driven by what the run produced, not by being asked. A run + whose build failed before writing the pair must not publish a partial entry + that every later run with the same star would then be served. + """ + cache = tmp_path / 'cache' + empty = tmp_path / 'run_empty' + empty.mkdir() + + assert store_in_cache(cache, 'abc123', empty) is False + assert not (cache / 'abc123.sf').exists() + + # Edge case: one file of the pair present is still nothing worth storing. + (empty / 'runtime.sf').write_bytes(b'prepared') + assert store_in_cache(cache, 'abc123', empty) is False + assert not (cache / 'abc123.sf').exists() + + # Discrimination: the complete pair does store, so the refusals above came + # from the missing file and not from a writer that always declines. + (empty / 'runtime.sf_k').write_bytes(b'prepared_k') + assert store_in_cache(cache, 'abc123', empty) is True + assert (cache / 'abc123.sf').is_file() + + +@pytest.mark.unit +def test_an_unusable_cache_costs_time_and_not_correctness(tmp_path): + """A cache that cannot be written or read leaves the run to build its own + file. Bookkeeping around a simulation must not decide whether it runs, so + both directions report the failure and return rather than raising. + """ + # A file where the cache folder should be: it cannot be created beneath. + blocked = tmp_path / 'not_a_directory' + blocked.write_text('this is a file, so no folder can be made beneath it') + + run = tmp_path / 'run' + _make_prepared(run) + assert store_in_cache(blocked, 'abc123', run) is False + + # Reading a cache folder that was never created is a miss, not an error. + assert seed_from_cache(tmp_path / 'never_made', 'abc123', tmp_path / 'out') is False + + # Discrimination: against a usable folder the same call succeeds, so the + # False above came from the blocked path rather than from a writer that + # always fails. + assert store_in_cache(tmp_path / 'cache', 'abc123', run) is True + + +@pytest.mark.unit +def test_storing_twice_leaves_one_usable_entry(tmp_path): + """Workers race to populate the same key, because they start together and + share a stellar spectrum. The later store replaces the earlier one in + place, so a reader sees one entry or the other and never a mixture. + """ + cache = tmp_path / 'cache' + first = tmp_path / 'run_0' + second = tmp_path / 'run_1' + _make_prepared(first, marker=b'from_first') + _make_prepared(second, marker=b'from_second') + + assert store_in_cache(cache, 'abc123', first) is True + assert store_in_cache(cache, 'abc123', second) is True + + # No temporary files survive to be mistaken for entries. + assert sorted(p.name for p in cache.iterdir()) == ['abc123.sf', 'abc123.sf_k'] + + out = tmp_path / 'run_2' + assert seed_from_cache(cache, 'abc123', out) is True + assert (out / 'runtime.sf').read_bytes() == b'from_second' + assert (out / 'runtime.sf_k').read_bytes() == b'from_second_k' diff --git a/tests/inference/test_async_bo.py b/tests/inference/test_async_bo.py index dc811de2a..7a0bfcf12 100644 --- a/tests/inference/test_async_bo.py +++ b/tests/inference/test_async_bo.py @@ -8,6 +8,8 @@ from __future__ import annotations +import logging + import pandas as pd import pytest @@ -223,10 +225,20 @@ class FakeProcess: def __init__(self, target, args): self.target = target self.args = args + self.exitcode = 0 created_processes.append(self) def start(self): - return None + # A worker that runs contributes at least one evaluation. Standing + # in for that keeps the dataset past the initial samples, which is + # what distinguishes a study that ran from one that did not. + shared = self.args[2] + shared['X'] = torch.cat( + (shared['X'], torch.tensor([[0.5]], dtype=torch.double)), dim=0 + ) + shared['Y'] = torch.cat( + (shared['Y'], torch.tensor([[0.7]], dtype=torch.double)), dim=0 + ) def join(self): return None @@ -269,7 +281,454 @@ def join(self): ) assert len(created_processes) == 2 - assert D_final['X'].shape == (1, 1) - assert D_final['Y'].shape == (1, 1) + # One initial sample plus one evaluation from each of the two workers. + assert D_final['X'].shape == (3, 1) + assert D_final['Y'].shape == (3, 1) assert logs == [None] assert elapsed == [] + + +# ============================================================================ +# Reporting workers that stop before the evaluation budget is reached +# ============================================================================ + + +def _mocked_parallel_process_env(monkeypatch, tmp_path, fake_process_cls, n_init_rows=1): + """Wire ``parallel_process`` to in-process fakes for the shared state. + + Returns nothing; the caller supplies the Process stand-in whose exit codes + and side effects define the scenario under test. + """ + + class FakeManager: + def dict(self, data=None): + return {} if data is None else dict(data) + + def list(self, data=None): + return [] if data is None else list(data) + + def Lock(self): + return _DummyLock() + + (tmp_path / 'init.csv').write_text('x_0,y\n0.1,0.2\n', encoding='utf-8') + monkeypatch.setattr( + async_mod, 'get_proteus_directories', lambda _output: {'output': str(tmp_path)} + ) + monkeypatch.setattr(async_mod, 'Manager', FakeManager) + monkeypatch.setattr(async_mod, 'Process', fake_process_cls) + monkeypatch.setattr( + async_mod, + 'load_dataset_csv', + lambda _path: { + 'X': torch.tensor([[0.1]] * n_init_rows, dtype=torch.double), + 'Y': torch.tensor([[0.2]] * n_init_rows, dtype=torch.double), + }, + ) + monkeypatch.setattr( + async_mod, + 'init_locs', + lambda n_workers, _D_shared, acqf='LogEI': torch.tensor( + [[0.2], [0.8]], dtype=torch.double + )[:n_workers], + ) + monkeypatch.setattr(async_mod, 'get_kernel', lambda *args, **kwargs: object()) + + +@pytest.mark.unit +def test_parallel_process_reports_a_worker_that_stopped_early(monkeypatch, tmp_path, caplog): + """A worker that dies mid-study leaves the run looking complete: the others + carry on and the results are saved. The shortfall is reported by worker id + and evaluation count so the summary that follows is not read as a full + sweep of the requested budget. + """ + + class FakeProcess: + _next = [0] + + def __init__(self, target, args): + self.args = args + self.worker_id = FakeProcess._next[0] + FakeProcess._next[0] += 1 + # Worker 1 is killed by a signal, as an out-of-memory kill does, + # which reports a negative code rather than a positive one. + # Worker 0 contributes one evaluation. + self.exitcode = -9 if self.worker_id == 1 else 0 + + def start(self): + if self.exitcode == 0: + shared = self.args[2] + shared['X'] = torch.cat( + (shared['X'], torch.tensor([[0.5]], dtype=torch.double)), dim=0 + ) + shared['Y'] = torch.cat( + (shared['Y'], torch.tensor([[0.7]], dtype=torch.double)), dim=0 + ) + + def join(self): + return None + + _mocked_parallel_process_env(monkeypatch, tmp_path, FakeProcess) + + with caplog.at_level('ERROR'): + D_final, _logs, _elapsed = async_mod.parallel_process( + objective_builder=lambda **kwargs: lambda x: x, + kernel='MAT3/2', + acqf='LogEI', + n_workers=2, + max_len=6, + output='dummy', + seed=1, + ref_config='ref.toml', + observables={'obs': 1.0}, + parameters={'a': [0.0, 1.0]}, + failure_codes=[], + ) + + # The partial study is still returned, so the evaluations that did complete + # are not thrown away. + assert D_final['X'].shape == (2, 1) + reported = '\n'.join(record.getMessage() for record in caplog.records) + # Identity guard: the dead worker is named, not merely counted. A + # regression that reported "1 worker failed" without the id would leave + # the user with nowhere to look. + assert 'workers 1' in reported + assert '1 of 2 workers' in reported + # The signal code is reported as it stands. A guard written as + # "exitcode > 0" would miss a killed worker entirely. + assert '-9' in reported + # Budget guard: the count actually achieved is contrasted with the count + # requested, which is what makes the shortfall visible. + assert '2 evaluations' in reported and '6 requested' in reported + + +@pytest.mark.unit +def test_parallel_process_stays_silent_when_every_worker_completes( + monkeypatch, tmp_path, caplog +): + """An inference run in which no worker died reports no shortfall. Without this, the + failure message above would be indistinguishable from routine noise. + """ + + class FakeProcess: + def __init__(self, target, args): + self.args = args + self.exitcode = 0 + + def start(self): + shared = self.args[2] + shared['X'] = torch.cat( + (shared['X'], torch.tensor([[0.5]], dtype=torch.double)), dim=0 + ) + shared['Y'] = torch.cat( + (shared['Y'], torch.tensor([[0.7]], dtype=torch.double)), dim=0 + ) + + def join(self): + return None + + _mocked_parallel_process_env(monkeypatch, tmp_path, FakeProcess) + + with caplog.at_level('ERROR'): + D_final, _logs, _elapsed = async_mod.parallel_process( + objective_builder=lambda **kwargs: lambda x: x, + kernel='MAT3/2', + acqf='LogEI', + n_workers=2, + max_len=6, + output='dummy', + seed=1, + ref_config='ref.toml', + observables={'obs': 1.0}, + parameters={'a': [0.0, 1.0]}, + failure_codes=[], + ) + + assert D_final['X'].shape == (3, 1) + assert [r for r in caplog.records if r.levelname == 'ERROR'] == [] + + +@pytest.mark.unit +def test_parallel_process_refuses_a_study_with_no_completed_steps(monkeypatch, tmp_path): + """When the dataset never grows past the initial samples there is no + optimisation to report, and the best-fit summary downstream would describe + the initial design while presenting it as an inference result. The study + stops instead, naming the reason. + """ + + class FakeProcess: + def __init__(self, target, args): + self.args = args + self.exitcode = 1 + + def start(self): + return None + + def join(self): + return None + + _mocked_parallel_process_env(monkeypatch, tmp_path, FakeProcess) + + with pytest.raises(RuntimeError) as excinfo: + async_mod.parallel_process( + objective_builder=lambda **kwargs: lambda x: x, + kernel='MAT3/2', + acqf='LogEI', + n_workers=2, + max_len=6, + output='dummy', + seed=1, + ref_config='ref.toml', + observables={'obs': 1.0}, + parameters={'a': [0.0, 1.0]}, + failure_codes=[], + ) + message = str(excinfo.value) + assert 'No optimisation steps completed' in message + # The cause is attributed to the workers, not to the evaluation budget, + # because they reported non-zero exit codes. + assert '2 of 2 workers stopped early' in message + + +@pytest.mark.unit +def test_worker_releases_its_busy_point_and_records_why_it_stopped(tmp_path, caplog): + """A worker that fails records the cause in the log before it dies, + and releases the point it had claimed. Neither happens on its own: + multiprocessing prints a dead worker's traceback straight to the parent's + stderr without consulting the logging configuration, and a claimed point + left in place steers the surviving workers away from a region nothing is + exploring. + """ + D_shared = { + 'X': torch.tensor([[0.1]], dtype=torch.double), + 'Y': torch.tensor([[0.2]], dtype=torch.double), + } + B = {0: torch.tensor([[0.3]], dtype=torch.double)} + + def exploding_process_fun(**_kwargs): + raise RuntimeError('objective evaluation failed') + + with caplog.at_level('ERROR'): + with pytest.raises(RuntimeError, match='objective evaluation failed'): + async_mod.worker( + process_fun=exploding_process_fun, + build_obj=lambda **kwargs: lambda x: x, + D_shared=D_shared, + B=B, + T=[], + T0=0.0, + x_init=torch.tensor([[0.3]], dtype=torch.double), + n_init=1, + lock=_DummyLock(), + max_len=4, + worker_id=0, + log_list=[], + output_dir=str(tmp_path), + ) + + # The claimed point is released. + assert 0 not in B + # The cause reached the study log, with a traceback attached. + records = [r for r in caplog.records if r.levelname == 'ERROR'] + assert any('Worker 0 stopped early' in r.getMessage() for r in records) + assert any(r.exc_info is not None for r in records) + # Nothing was appended to the shared dataset, so a failed evaluation + # cannot masquerade as a completed one. + assert D_shared['X'].shape == (1, 1) + + +@pytest.mark.unit +def test_worker_releases_its_busy_point_after_a_normal_finish(tmp_path): + """A worker that reaches the evaluation budget also releases its claimed + point. + """ + D_shared = { + 'X': torch.tensor([[0.1], [0.2]], dtype=torch.double), + 'Y': torch.tensor([[0.3], [0.4]], dtype=torch.double), + } + B = { + 0: torch.tensor([[0.5]], dtype=torch.double), + 1: torch.tensor([[0.6]], dtype=torch.double), + } + + # max_len is already reached, so the loop exits without an evaluation. + async_mod.worker( + process_fun=lambda **_kwargs: pytest.fail('no evaluation should run'), + build_obj=lambda **kwargs: lambda x: x, + D_shared=D_shared, + B=B, + T=[], + T0=0.0, + x_init=torch.tensor([[0.5]], dtype=torch.double), + n_init=2, + lock=_DummyLock(), + max_len=2, + worker_id=0, + log_list=[], + output_dir=str(tmp_path), + ) + + assert 0 not in B + # Only this worker's claim is released; the other worker is still running. + assert 1 in B + + +@pytest.mark.unit +def test_parallel_process_names_the_real_step_budget_when_no_worker_failed( + monkeypatch, tmp_path +): + """An inference run configured with fewer optimisation steps than workers finishes + without any worker failing and without any step being taken. The refusal + must name the condition in the quantities the user set, n_steps against + n_workers, since the internal row threshold the workers apply is not a + number that appears anywhere in the study config. + """ + + class FakeProcess: + def __init__(self, target, args): + self.args = args + self.exitcode = 0 + + def start(self): + # Every worker sees the budget already met and exits at once, + # contributing nothing to the dataset. + return None + + def join(self): + return None + + # One optimisation step across two workers, the smallest configuration that + # reaches this branch: the worker threshold is 7 - (2 - 1) = 6, which the + # six initial samples already meet. + _mocked_parallel_process_env(monkeypatch, tmp_path, FakeProcess, n_init_rows=6) + + with pytest.raises(RuntimeError) as excinfo: + async_mod.parallel_process( + objective_builder=lambda **kwargs: lambda x: x, + kernel='MAT3/2', + acqf='LogEI', + n_workers=2, + max_len=7, + output='dummy', + seed=1, + ref_config='ref.toml', + observables={'obs': 1.0}, + parameters={'a': [0.0, 1.0]}, + failure_codes=[], + ) + message = str(excinfo.value) + assert 'No worker failed' in message + # Named in the config's own terms: one step requested, two workers to run it. + assert '1 optimisation step across 2 workers' in message + assert 'Raise n_steps to at least n_workers (2)' in message + + +@pytest.mark.unit +def test_worker_writes_its_traceback_to_the_study_logfile(tmp_path): + """A worker started with the 'spawn' method inherits no logging + configuration, so the report of its death would go to stderr and never + reach the logfile. Given the logfile path, the worker reopens it + and the traceback lands where the study is read from. + + The 'fwl' logger is emptied here to stand in for a spawned process, which + is what the parent's handlers are absent in; pytest's own capture would + otherwise hide the gap this covers. + """ + logger = logging.getLogger('fwl') + saved_handlers, saved_level = list(logger.handlers), logger.level + logger.handlers.clear() + + logpath = tmp_path / 'infer.log' + logpath.write_text('[ INFO ] study started\n', encoding='utf-8') + + D_shared = { + 'X': torch.tensor([[0.1]], dtype=torch.double), + 'Y': torch.tensor([[0.2]], dtype=torch.double), + } + # Keyed by this worker's own id, so the release below is a real check. + B = {3: torch.tensor([[0.3]], dtype=torch.double)} + + def exploding_process_fun(**_kwargs): + raise RuntimeError('objective evaluation failed') + + try: + with pytest.raises(RuntimeError, match='objective evaluation failed'): + async_mod.worker( + process_fun=exploding_process_fun, + build_obj=lambda **kwargs: lambda x: x, + D_shared=D_shared, + B=B, + T=[], + T0=0.0, + x_init=torch.tensor([[0.3]], dtype=torch.double), + n_init=1, + lock=_DummyLock(), + max_len=4, + worker_id=3, + log_list=[], + output_dir=str(tmp_path), + logpath=str(logpath), + log_level=logging.INFO, + ) + for handler in logging.getLogger('fwl').handlers: + handler.flush() + text = logpath.read_text(encoding='utf-8') + finally: + logger.handlers.clear() + logger.handlers.extend(saved_handlers) + logger.setLevel(saved_level) + + assert 'Worker 3 stopped early' in text + # The cause, not just the headline: a report without the traceback body + # would leave the study with no more than the fact that something failed. + assert 'RuntimeError: objective evaluation failed' in text + # Appended, never recreated: the lines written before the worker started + # are what place the failure in the run. + assert 'study started' in text + # The busy point is still released on the way out, so the logfile change + # has not displaced the behaviour the failure path already had. + assert B == {} + + +@pytest.mark.unit +def test_worker_without_a_logfile_path_leaves_logging_untouched(tmp_path, caplog): + """Under 'fork' the parent's handlers are inherited, so `parallel_process` + passes no path and the worker must not attach one of its own; a second + handler on the same file would double every line. The failure is still + reported through whatever configuration the process already has. + """ + logger = logging.getLogger('fwl') + before = list(logger.handlers) + + D_shared = { + 'X': torch.tensor([[0.1]], dtype=torch.double), + 'Y': torch.tensor([[0.2]], dtype=torch.double), + } + B = {0: torch.tensor([[0.3]], dtype=torch.double)} + + def exploding_process_fun(**_kwargs): + raise RuntimeError('objective evaluation failed') + + with caplog.at_level('ERROR'): + with pytest.raises(RuntimeError, match='objective evaluation failed'): + async_mod.worker( + process_fun=exploding_process_fun, + build_obj=lambda **kwargs: lambda x: x, + D_shared=D_shared, + B=B, + T=[], + T0=0.0, + x_init=torch.tensor([[0.3]], dtype=torch.double), + n_init=1, + lock=_DummyLock(), + max_len=4, + worker_id=0, + log_list=[], + output_dir=str(tmp_path), + ) + + # No handler added, and none taken away. + assert list(logger.handlers) == before + # No stray logfile created beside the run output. + assert not (tmp_path / 'infer.log').exists() + reported = '\n'.join(record.getMessage() for record in caplog.records) + assert 'Worker 0 stopped early' in reported diff --git a/tests/inference/test_bo.py b/tests/inference/test_bo.py index 4ac04a434..863c56ced 100644 --- a/tests/inference/test_bo.py +++ b/tests/inference/test_bo.py @@ -423,3 +423,113 @@ def test_quadratic_objective_returns_zero_at_target(): y_near = objective(torch.tensor([[0.45, 0.55]], dtype=torch.double)) # ratio of (far-target)^2 to (near-target)^2 = ((0.3,0.3))^2 / ((0.15,0.15))^2 = 4 assert y_near.item() / y_far.item() == pytest.approx(0.25, rel=1e-9) + + +# ============================================================================ +# Busy-point bookkeeping when workers come and go +# ============================================================================ + + +def _patched_bo_step_deps(monkeypatch, candidate=0.8): + """Replace the GP fit and acquisition optimisation with fixed stand-ins. + + Leaves the busy-point handling under test as the only live logic. + """ + monkeypatch.setattr(bo_mod, 'SingleTaskGP', lambda **kwargs: _DummyGP()) + monkeypatch.setattr(bo_mod, 'ExactMarginalLogLikelihood', lambda _lik, _gp: object()) + monkeypatch.setattr(bo_mod, 'fit_gpytorch_mll', lambda *args, **kwargs: None) + monkeypatch.setattr(bo_mod, 'get_acqf', lambda *args, **kwargs: object()) + monkeypatch.setattr( + bo_mod, + 'optimize_acqf', + lambda **kwargs: (torch.tensor([[candidate]], dtype=torch.double), None), + ) + monkeypatch.setattr(bo_mod, 'plot_iter', lambda **kwargs: None) + + +@pytest.mark.unit +def test_bo_step_identifies_busy_points_by_worker_id_not_position(monkeypatch): + """Busy points are matched to their owner by worker id. Once a worker has + stopped and released its claim, the remaining entries no longer sit at the + position their worker id implies, so a positional lookup reads another + worker's point as its own. + """ + _patched_bo_step_deps(monkeypatch, candidate=0.8) + + D = { + 'X': torch.tensor([[0.1]], dtype=torch.double), + 'Y': torch.tensor([[1.0]], dtype=torch.double), + } + # Worker 1 has stopped and released its point. Worker 2 is still running, + # and is the caller here: its own claim must be excluded, the others kept. + # Two other workers are present so the nearest is not also the furthest, + # which a single other point would make indistinguishable. + B = { + 0: torch.tensor([[0.1]], dtype=torch.double), + 2: torch.tensor([[0.75]], dtype=torch.double), + 3: torch.tensor([[0.79]], dtype=torch.double), + } + + _x, y, *_rest, dist = bo_mod.BO_step( + D=D, + B=B, + f=lambda _x: torch.tensor([[0.9]], dtype=torch.double), + k=object(), + acqf='UCB', + lock=_DummyLock(), + worker_id=2, + ) + + assert y[0, 0].item() == pytest.approx(0.9) + # Nearest other claim is worker 3 at 0.79, from the candidate at 0.8. + assert dist == pytest.approx(0.01) + # Nearest, not furthest: worker 0 sits at 0.1, giving 0.7. A regression to + # torch.max would report that instead. + assert abs(dist - 0.7) > 0.5 + # The caller's own claim at 0.75 is excluded. Including it would give + # 0.05, which is neither of the two values above. + assert abs(dist - 0.05) > 0.02 + + +@pytest.mark.unit +def test_bo_step_reports_no_distance_when_no_other_worker_is_busy(monkeypatch): + """With no other worker running, there is no nearest busy point and the + distance is undefined rather than zero. This is the steady state of a + single-worker study and the tail of every multi-worker one. + """ + _patched_bo_step_deps(monkeypatch, candidate=0.4) + + D = { + 'X': torch.tensor([[0.1]], dtype=torch.double), + 'Y': torch.tensor([[1.0]], dtype=torch.double), + } + B = {0: torch.tensor([[0.2]], dtype=torch.double)} + + x, y, *_rest, dist = bo_mod.BO_step( + D=D, + B=B, + f=lambda _x: torch.tensor([[0.6]], dtype=torch.double), + k=object(), + acqf='UCB', + lock=_DummyLock(), + worker_id=0, + ) + + # The step still completes and proposes its candidate. + assert x[0, 0].item() == pytest.approx(0.4) + assert y[0, 0].item() == pytest.approx(0.6) + # Undefined, not zero: a zero would read as another worker sitting exactly + # on this candidate and would suppress the diversity term. + assert dist is None + + # Edge case: an entirely empty busy map behaves the same way. + _x2, _y2, *_rest2, dist2 = bo_mod.BO_step( + D=D, + B={}, + f=lambda _x: torch.tensor([[0.6]], dtype=torch.double), + k=object(), + acqf='UCB', + lock=_DummyLock(), + worker_id=0, + ) + assert dist2 is None diff --git a/tests/inference/test_failures.py b/tests/inference/test_failures.py new file mode 100644 index 000000000..05c81fa9b --- /dev/null +++ b/tests/inference/test_failures.py @@ -0,0 +1,488 @@ +""" +Unit tests for recording and reporting unscored inference evaluations. + +Covers `proteus.inference.failures`: what a failed or excluded evaluation +carries, how one is appended to the study's failure table without workers +contending for it, how that table is read back, and the end-of-study tally. + +References: + - docs/How-to/testing.md + - docs/Explanations/test_framework.md +""" + +from __future__ import annotations + +import logging +import pickle +import re + +import pandas as pd +import pytest + +import proteus.inference.failures as failures_mod + +pytestmark = [pytest.mark.unit, pytest.mark.timeout(30)] + + +def _counts(line: str) -> list[str]: + """Every number in a log line, in order. + + The tally lines are prose around a handful of counts. Asserting on the + numbers keeps a test pinned to what the reader has to get right, and lets + the wording be changed without a test failing for no reason. Order is kept, + so a line that swapped the failed and excluded counts still fails. + """ + return re.findall(r'\d+(?:\.\d+)?', line) + + +@pytest.mark.unit +def test_failure_summary_is_one_line_and_names_where_the_detail_is_kept(): + """The line a study logs for each unscored run identifies the run, names + the status code and points at the output folder, and stays on one line + however many parameters the study sweeps. The swept values and the paths to + open next belong to the fuller report, not to the one-liner. + """ + # Edge case: a wide sweep is the situation the one-liner exists for. Twenty + # parameters rendered inline would run past any terminal width. + swept = {f'planet.param_{i}': float(i) for i in range(20)} + swept['planet.mass_tot'] = 1.25 + failure = failures_mod.ProteusRunFailure( + reason='the simulator exited with an error', + worker=2, + iter=16, + out_dir='/study/workers/w_2/i_16', + exit_code=1, + status=22, + log_path='/study/workers/w_2/i_16/proteus_00.log', + console_path='/study/workers/w_2/i_16_console.log', + parameters=swept, + ) + line = failure.summary() + + assert '\n' not in line + assert 'planet.mass_tot' not in line + assert 'proteus_00.log' not in line + # What has to survive the trim: who failed, what the status was, and the + # folder holding the logfile and the console capture. + assert 'worker=2 iter=16' in line + assert 'status 22' in line + assert 'Atmosphere' in line + assert 'exit code 1' in line + assert '/study/workers/w_2/i_16' in line + # Discrimination: the detail is not lost, only moved. A regression that + # trimmed `report` instead of adding a second renderer would fail here. + rendered = failure.report() + assert 'planet.mass_tot=1.25' in rendered + assert 'proteus_00.log' in rendered + assert 'i_16_console.log' in rendered + # The report opens with the same one-liner, so nothing the summary names is + # dropped on the way to the fuller form. + assert rendered.splitlines()[0] == line + + # Limit input: an excluded run has nothing to report as a fault, so it is + # named as excluded and its exit code, always zero on that path, is left + # out rather than read as a crash code. + excluded = failures_mod.ProteusRunFailure( + reason='completed on a status this study excludes', + worker=0, + iter=10, + out_dir='/study/workers/w_0/i_10', + exit_code=0, + status=11, + category=failures_mod.CATEGORY_EXCLUDED, + ) + excluded_line = excluded.summary() + assert '\n' not in excluded_line + assert 'excluded for worker=0 iter=10' in excluded_line + assert 'failed for worker=0' not in excluded_line + assert 'exit code' not in excluded_line + assert 'status 11' in excluded_line + + +@pytest.mark.unit +def test_proteus_run_failure_survives_the_trip_back_from_a_pool_worker(): + """A failure raised inside a pool worker is pickled and re-raised in the + parent process. Every reported field must survive that round trip, or the + parent sees a reconstruction error in place of the diagnosis. + """ + original = failures_mod.ProteusRunFailure( + reason='the simulator exited with an error', + worker=2, + iter=7, + out_dir='/study/workers/w_2/i_7', + exit_code=1, + status=27, + log_path='/study/workers/w_2/i_7/proteus_00.log', + console_path='/study/workers/w_2/i_7_console.log', + parameters={'planet.mass_tot': 2.0}, + ) + restored = pickle.loads(pickle.dumps(original)) + + assert isinstance(restored, failures_mod.ProteusRunFailure) + assert restored.report() == original.report() + # Field-level guard: an equal report could still hide a dropped field that + # the renderer omits when empty, so pin the values that steer diagnosis. + assert restored.status == 27 + assert restored.worker == 2 and restored.iter == 7 + assert restored.parameters == {'planet.mass_tot': pytest.approx(2.0)} + assert restored.log_path == original.log_path + assert restored.console_path == original.console_path + assert restored.category == failures_mod.CATEGORY_FAILURE + + # The category rides along in the same tuple, and it decides whether the + # parent calls the run a fault. A field dropped from the reconstruction + # would fall back to the 'failure' default and go unnoticed on a failure, + # so the round trip is checked on the other value too. + excluded = failures_mod.ProteusRunFailure( + reason='completed on a status this study excludes', + worker=2, + iter=7, + out_dir='/study/workers/w_2/i_7', + exit_code=0, + status=11, + category=failures_mod.CATEGORY_EXCLUDED, + ) + restored_excluded = pickle.loads(pickle.dumps(excluded)) + assert restored_excluded.category == failures_mod.CATEGORY_EXCLUDED + assert 'excluded for worker=2' in restored_excluded.report() + assert 'failed for worker=2' not in restored_excluded.report() + + +@pytest.mark.unit +def test_failure_records_round_trip_into_one_table(tmp_path): + """Each worker appends its own row to the study's failure table, and the + rows are read back ordered by worker then iteration whatever order they + arrived in. The status description is stored rather than recomputed, so the + summary does not have to re-derive it from the code. + """ + first = failures_mod.ProteusRunFailure( + reason='the simulator exited with an error', + worker=0, + iter=5, + out_dir='/study/workers/w_0/i_5', + exit_code=1, + status=21, + parameters={'planet.mass_tot': 3.0}, + ) + # Same iteration, different worker: two rows, not one overwriting the other. + second = failures_mod.ProteusRunFailure( + reason='exceeded the 3600.0 s timeout', + worker=1, + iter=5, + out_dir='/study/workers/w_1/i_5', + status=failures_mod.STATUS_MISSING, + parameters={'planet.mass_tot': 4.0}, + ) + + # Written out of order: the second worker fails first. + assert failures_mod.record_failure(tmp_path, second) is not None + assert failures_mod.record_failure(tmp_path, first) is not None + table = tmp_path / failures_mod.FAILURE_CSV + # One header however many workers append, so the table parses as one frame. + assert table.read_text().count('worker,iter,') == 1 + + records = failures_mod.read_failure_records(tmp_path) + # Ordering guard: written second-then-first, read back in worker order. + assert [r['worker'] for r in records] == [0, 1] + assert records[0]['status'] == 21 + assert records[0]['status_desc'] == first.status_desc + # Swept values are columns of their own, so the table can be sorted on a + # parameter to see which region of the box fails. + assert records[0]['planet.mass_tot'] == pytest.approx(3.0) + assert records[1]['planet.mass_tot'] == pytest.approx(4.0) + # A run that never wrote a status file is stored as such, not as a generic + # error, so the summary can separate start-up deaths from model faults. + assert records[1]['status'] == failures_mod.STATUS_MISSING + assert 'no readable status file' in records[1]['status_desc'] + # An absent exit code reads back as None, not as the string 'nan', which + # would print into the summary as though it were a code the child returned. + assert records[1]['exit_code'] is None + + # Edge case: a field holding the delimiter is quoted on the way out, or it + # would shift every later column of that row by one. + comma = failures_mod.ProteusRunFailure( + reason='the simulator exited with an error, code 3', + worker=2, + iter=0, + out_dir='/study/workers/w_2/i_0', + exit_code=3, + status=21, + parameters={'planet.mass_tot': 5.0}, + ) + assert failures_mod.record_failure(tmp_path, comma) is not None + reread = failures_mod.read_failure_records(tmp_path)[-1] + assert reread['reason'] == 'the simulator exited with an error, code 3' + assert reread['planet.mass_tot'] == pytest.approx(5.0) + + # Edge case: a table that cannot be parsed is reported and treated as empty + # rather than aborting the summary it feeds. A zero-length file is the + # reachable form of this: a worker killed between creating the table and + # writing its first row leaves exactly that behind. + table.write_text('') + assert failures_mod.read_failure_records(tmp_path) == [] + + +@pytest.mark.unit +def test_recording_a_failure_never_masks_the_failure_it_records(tmp_path): + """Bookkeeping must not bring down a study. When the record cannot be + written the writer reports that it could not, and the caller still has the + failure in hand to log and to score. + """ + blocked = tmp_path / 'not_a_directory' + blocked.write_text('this is a file, so no folder can be made beneath it') + failure = failures_mod.ProteusRunFailure( + reason='the simulator exited with an error', + worker=0, + iter=0, + out_dir=str(tmp_path), + exit_code=1, + status=21, + ) + + assert failures_mod.record_failure(blocked, failure) is None + # Discrimination: the same failure records fine against a usable folder, so + # the None above came from the blocked path and not from a writer that + # always fails. + assert failures_mod.record_failure(tmp_path / 'study', failure) is not None + # Reading a study that never created the folder is empty, not an error. + assert failures_mod.read_failure_records(tmp_path / 'never_ran') == [] + + +@pytest.mark.unit +def test_summarise_failures_tabulates_causes_and_warns_on_every_real_failure(tmp_path, caplog): + """The end-of-study tally turns the per-run rows into one table and one + breakdown by cause, and warns whenever a run produced nothing usable. The + warning does not wait for a fraction of the study to fail: a sweep can lose + a tenth of its evaluations and still fit well, so the count is put in front + of the reader to weigh rather than compared against a threshold. + """ + + # Two runs that died the same way and one that died differently, so the + # breakdown has something to group. + for worker, status in ((0, 21), (1, 21), (2, 24)): + failures_mod.record_failure( + tmp_path, + failures_mod.ProteusRunFailure( + reason='the simulator exited with an error', + worker=worker, + iter=0, + out_dir=f'/study/workers/w_{worker}/i_0', + exit_code=1, + status=status, + parameters={'planet.mass_tot': 1.0 + worker}, + ), + ) + + with caplog.at_level(logging.INFO, logger='fwl.proteus.inference.failures'): + n_failed = failures_mod.summarise_failures(str(tmp_path), n_attempted=20) + + assert n_failed == 3 + messages = '\n'.join(r.message for r in caplog.records) + assert '3 of 20' in messages + # Grouped by cause, so two runs that died the same way count as one line. + assert 'Interior model' in messages + + # 3 of 20 is 15%, well under the half-the-study line the old threshold drew, + # and it is raised to a warning anyway: the count is what the reader weighs. + # One record carries it, so the level changes rather than a second line + # repeating the counts the report already gave. + warnings = [r for r in caplog.records if r.levelname == 'WARNING'] + assert len(warnings) == 1 + # unscored, attempted, percent, failed, excluded. + assert _counts(warnings[0].message) == ['3', '20', '15.0', '3', '0'] + + # The table carries the swept parameter alongside the diagnosis, so the + # failing region can be located without opening each run folder. + table = pd.read_csv(tmp_path / 'failures.csv') + assert len(table) == 3 + assert list(table['worker']) == [0, 1, 2] + assert sorted(table['status']) == [21, 21, 24] + assert table['planet.mass_tot'].max() == pytest.approx(3.0) + + # The percentage tracks the study size rather than being a fixed string: + # the same three failures against a smaller study report a larger share. + caplog.clear() + with caplog.at_level(logging.INFO, logger='fwl.proteus.inference.failures'): + failures_mod.summarise_failures(str(tmp_path), n_attempted=4) + warnings = [r for r in caplog.records if r.levelname == 'WARNING'] + assert len(warnings) == 1 + assert _counts(warnings[0].message) == ['3', '4', '75.0', '3', '0'] + + +@pytest.mark.unit +def test_summarise_failures_counts_excluded_outcomes_apart_from_failures(tmp_path, caplog): + """A run that completed on a status the study excludes is tallied, but not + as a fault. Folding the two together would tell the user that a study whose + runs all reached their clock limit, exactly as configured, is a study full + of broken simulations. + """ + + failures_mod.record_failure( + tmp_path, + failures_mod.ProteusRunFailure( + reason='the simulator exited with an error', + worker=0, + iter=0, + out_dir='/study/workers/w_0/i_0', + exit_code=1, + status=21, + parameters={'planet.mass_tot': 1.0}, + ), + ) + for worker in (1, 2): + failures_mod.record_failure( + tmp_path, + failures_mod.ProteusRunFailure( + reason='completed on a status this study excludes', + worker=worker, + iter=0, + out_dir=f'/study/workers/w_{worker}/i_0', + exit_code=0, + status=11, + parameters={'planet.mass_tot': 1.0 + worker}, + category=failures_mod.CATEGORY_EXCLUDED, + ), + ) + + with caplog.at_level(logging.INFO, logger='fwl.proteus.inference.failures'): + n_unscored = failures_mod.summarise_failures(str(tmp_path), n_attempted=20) + + # Both kinds are unscored, so both count toward how much of the study was + # real, but the breakdown names them apart. + assert n_unscored == 3 + messages = '\n'.join(r.message for r in caplog.records) + tally = next(r for r in caplog.records if 'Unscored evaluations' in r.message) + # unscored, attempted, percent, failed, excluded: the one fault is counted + # apart from the two runs that completed on an excluded status. + assert _counts(tally.message) == ['3', '20', '15.0', '1', '2'] + # The clock-limit outcome is labelled in the cause table rather than being + # listed beside the interior-model error as if it were one. + assert 'Completed (maximum clock runtime) [excluded]' in messages + assert 'Error (Interior model) [excluded]' not in messages + + # Carried into the table too, so the excluded rows can be filtered out when + # looking for the region that actually breaks the simulator. + table = pd.read_csv(tmp_path / 'failures.csv') + assert sorted(table['category']) == ['excluded', 'excluded', 'failure'] + assert sorted(table.loc[table['category'] == 'excluded', 'status']) == [11, 11] + + # Raised to a warning by the one genuine fault. The counts were pinned + # above; what matters here is that the line carrying them is the warning. + assert [r.levelname for r in caplog.records if r.levelname == 'WARNING'] == ['WARNING'] + assert 'Unscored evaluations' in tally.message and tally.levelname == 'WARNING' + + # Limit input: a study whose runs were *all* excluded did exactly what it + # was configured to do, so it is tallied without any warning at all. Keying + # the warning on the unscored total would have flagged it as broken. + caplog.clear() + (tmp_path / 'failures.csv').unlink() + for worker in (0, 1): + failures_mod.record_failure( + tmp_path, + failures_mod.ProteusRunFailure( + reason='completed on a status this study excludes', + worker=worker, + iter=0, + out_dir=f'/study/workers/w_{worker}/i_0', + exit_code=0, + status=11, + parameters={'planet.mass_tot': 1.0 + worker}, + category=failures_mod.CATEGORY_EXCLUDED, + ), + ) + with caplog.at_level(logging.INFO, logger='fwl.proteus.inference.failures'): + assert failures_mod.summarise_failures(str(tmp_path), n_attempted=4) == 2 + assert not [r for r in caplog.records if r.levelname == 'WARNING'] + # Discrimination: 2 of 4 is half the study, which the old fraction rule + # would have reported as a study mostly not worth trusting. + assert '2 of 4' in '\n'.join(r.message for r in caplog.records) + + +@pytest.mark.unit +def test_summarise_failures_reports_a_clean_study_without_writing_a_table(tmp_path, caplog): + """A study in which nothing failed says so and writes no table. An empty + failures.csv would suggest the accounting had run and found nothing to + say about a study that in fact had nothing to report. + """ + + with caplog.at_level(logging.INFO, logger='fwl.proteus.inference.failures'): + n_failed = failures_mod.summarise_failures(str(tmp_path), n_attempted=12) + + assert n_failed == 0 + assert not (tmp_path / 'failures.csv').exists() + messages = '\n'.join(r.message for r in caplog.records) + assert 'none' in messages and '12' in _counts(messages) + assert not [r for r in caplog.records if r.levelname in ('WARNING', 'ERROR')] + + +@pytest.mark.unit +def test_summarise_failures_labels_the_logfile_sample_and_counts_the_whole_study( + tmp_path, caplog +): + """The tally covers every evaluation attempted, initial samples included, + while the warning raised alongside the best fit covers the optimisation + steps alone. The logfile lines are a sample of at most three, so they are + labelled with how many of the total they show and printed above the pointer + to the full table; unlabelled, three paths below a "Full list" line read as + the complete set. + """ + + # Four records, the first of which has no logfile: the run died before the + # child wrote one. The sample must skip it and still offer three paths. + for worker in range(4): + failures_mod.record_failure( + tmp_path, + failures_mod.ProteusRunFailure( + reason='the simulator exited with an error', + worker=worker, + iter=0, + out_dir=f'/study/workers/w_{worker}/i_0', + exit_code=1, + status=21, + log_path=None if worker == 0 else f'/study/w_{worker}/proteus_00.log', + parameters={'planet.mass_tot': 1.0 + worker}, + ), + ) + + with caplog.at_level(logging.INFO, logger='fwl.proteus.inference.failures'): + failures_mod.summarise_failures(str(tmp_path), n_attempted=20) + + lines = [r.message for r in caplog.records] + messages = '\n'.join(lines) + # The denominator of the tally is the whole study, stated in the line + # itself so it cannot be confused with the optimisation-only warning. + assert '4 of 20' in messages + # Three shown out of four unscored, not four out of four. + assert '3 of 4 shown' in messages + shown = [line.strip() for line in lines if line.strip().endswith('proteus_00.log')] + assert len(shown) == 3 + # The record without a logfile is skipped rather than truncating the + # sample to the two paths that follow it in the first three records. + assert '/study/w_1/proteus_00.log' in shown + assert '/study/w_3/proteus_00.log' in shown + + # The pointer to the complete table comes after the sample, so the sample + # cannot be read as a continuation of it. + i_sample = next(i for i, line in enumerate(lines) if line.startswith('Logfiles (')) + i_full = next(i for i, line in enumerate(lines) if line.startswith('Full list:')) + assert i_sample < i_full + + # Discrimination: with no logfile recorded anywhere, no sample block is + # emitted at all, so the label tracks the data rather than always printing. + caplog.clear() + (tmp_path / 'failures.csv').rename(tmp_path / 'failures_old.csv') + failures_mod.record_failure( + tmp_path, + failures_mod.ProteusRunFailure( + reason='the simulator exited with an error', + worker=0, + iter=1, + out_dir='/study/workers/w_0/i_1', + exit_code=1, + status=21, + parameters={'planet.mass_tot': 1.0}, + ), + ) + with caplog.at_level(logging.INFO, logger='fwl.proteus.inference.failures'): + failures_mod.summarise_failures(str(tmp_path), n_attempted=20) + assert not [r for r in caplog.records if r.message.startswith('Logfiles (')] diff --git a/tests/inference/test_inference.py b/tests/inference/test_inference.py index 228289408..a75997d9b 100644 --- a/tests/inference/test_inference.py +++ b/tests/inference/test_inference.py @@ -10,6 +10,7 @@ from __future__ import annotations import multiprocessing as mp +from pathlib import Path import pytest import toml @@ -22,9 +23,12 @@ pytest.importorskip('gpytorch') import proteus.inference.inference as inference_mod # noqa: E402 +from proteus.config import UnknownConfigKeyError # noqa: E402 pytestmark = [pytest.mark.unit, pytest.mark.timeout(30)] +BASE_CONFIG = str(Path(__file__).parent / 'base.toml') + # Pytest can hang on process completion when using multiprocessing by default. mp.set_start_method('spawn', force=True) @@ -140,6 +144,187 @@ def fake_run_inference(cfg): assert set(observed['config'].keys()) == set(expected.keys()) +# ============================================================================ +# Reference-config validation before any worker is launched +# ============================================================================ + + +@pytest.mark.unit +def test_parameter_bounds_converts_pairs_and_rejects_malformed_ranges(): + """``parameter_bounds`` accepts an increasing pair of numbers and returns + it as floats, and rejects every other shape a user could write: a single + value, a non-numeric entry, a decreasing pair, and the degenerate pair + where the two ends coincide and the parameter has no range to search. + """ + converted = inference_mod.parameter_bounds( + {'planet.mass_tot': [1, 3], 'interior_struct.core_frac': (0.3, 0.7)} + ) + assert converted['planet.mass_tot'] == (pytest.approx(1.0), pytest.approx(3.0)) + # Integer TOML literals must arrive as floats, matching the values the + # optimiser writes back into each worker's config. + assert all(isinstance(v, float) for v in converted['planet.mass_tot']) + assert converted['interior_struct.core_frac'] == ( + pytest.approx(0.3), + pytest.approx(0.7), + ) + + with pytest.raises(ValueError, match='pair of numbers'): + inference_mod.parameter_bounds({'planet.mass_tot': [1.0]}) + with pytest.raises(ValueError, match='pair of numbers'): + inference_mod.parameter_bounds({'planet.mass_tot': 'auto'}) + with pytest.raises(ValueError, match='must increase'): + inference_mod.parameter_bounds({'planet.mass_tot': [3.0, 1.0]}) + # Edge case: coincident bounds are a zero-width range, not a fixed value. + with pytest.raises(ValueError, match='must increase'): + inference_mod.parameter_bounds({'planet.mass_tot': [2.0, 2.0]}) + # Edge case: TOML admits `inf`, which satisfies "increases" and clears the + # schema's own range checks, then makes every unnormalised sample infinite. + with pytest.raises(ValueError, match='must be finite'): + inference_mod.parameter_bounds({'planet.mass_tot': [1.0, float('inf')]}) + with pytest.raises(ValueError, match='must be finite'): + inference_mod.parameter_bounds({'planet.mass_tot': [float('nan'), 3.0]}) + + +@pytest.mark.unit +def test_validate_reference_config_accepts_a_runnable_sweep(): + """A reference config that PROTEUS accepts, swept over parameters that stay + inside the schema at both ends, passes validation. Each accepted sweep is + paired with a neighbouring rejected one, so a validator gutted to an + immediate return fails this test rather than passing it. + """ + bounds = {'planet.mass_tot': [0.7, 3.0], 'interior_struct.core_frac': [0.3, 0.9]} + inference_mod.validate_reference_config(BASE_CONFIG, bounds) + # Liveness: widening one range past the schema limit must be refused, which + # proves the accepted case above was actually checked. + with pytest.raises(ValueError) as excinfo: + inference_mod.validate_reference_config( + BASE_CONFIG, {**bounds, 'interior_struct.core_frac': [0.3, 1.5]} + ) + assert 'core_frac' in str(excinfo.value) + # Only the widened range is at fault; the untouched one must not be named. + assert 'mass_tot' not in str(excinfo.value) + + # Edge case: an empty sweep still validates the file itself, so a broken + # reference config is caught even when nothing is being optimised. + inference_mod.validate_reference_config(BASE_CONFIG, {}) + + +@pytest.mark.unit +def test_validate_reference_config_rejects_a_mistyped_parameter_name(): + """A parameter name that no config field matches is reported as an + unrecognised key. Without this check the name would be written into each + worker's config as a new orphan section and every worker would refuse to + start, midway through the study. + """ + bounds = {'planet.mass_tott': [0.7, 3.0]} + with pytest.raises(UnknownConfigKeyError) as excinfo: + inference_mod.validate_reference_config(BASE_CONFIG, bounds) + + message = str(excinfo.value) + assert 'planet.mass_tott' in message + # The key is absent from the file on disk, so the message must say the + # sweep introduced it rather than blaming the reference config alone. + assert 'bounds' in message + # Discrimination: the correctly spelled name must not be flagged, which + # would happen if the walk reported every swept key rather than orphans. + assert 'planet.mass_tot"' not in message + + +@pytest.mark.unit +def test_validate_reference_config_rejects_a_bound_outside_the_schema_range(): + """A range whose upper end leaves the interval the schema allows is + rejected, and the message names the end that failed. ``core_frac`` is + constrained to the open interval (0, 1), so 0.3 is accepted and 1.5 is + not; only a check at both ends of the range catches this. + """ + with pytest.raises(ValueError, match='upper bounds'): + inference_mod.validate_reference_config( + BASE_CONFIG, {'interior_struct.core_frac': [0.3, 1.5]} + ) + # The same fault at the other end is attributed to the other end. + with pytest.raises(ValueError, match='lower bounds'): + inference_mod.validate_reference_config( + BASE_CONFIG, {'interior_struct.core_frac': [-0.2, 0.9]} + ) + # Discrimination: a range wholly inside (0, 1) must pass, so the failures + # above come from the bounds and not from the reference config itself. + inference_mod.validate_reference_config( + BASE_CONFIG, {'interior_struct.core_frac': [0.3, 0.9]} + ) + + +@pytest.mark.unit +def test_validate_reference_config_rejects_a_faulty_reference_file(tmp_path): + """A fault in the reference config itself is attributed to the file, not + to the parameter sweep, so the user knows which file to edit. + """ + raw = toml.load(BASE_CONFIG) + raw['planet']['mass_tott'] = 1.0 + faulty = tmp_path / 'faulty.toml' + faulty.write_text(toml.dumps(raw), encoding='utf-8') + + with pytest.raises(UnknownConfigKeyError) as excinfo: + inference_mod.validate_reference_config(str(faulty), {'planet.mass_tot': [0.7, 3.0]}) + + message = str(excinfo.value) + assert 'planet.mass_tott' in message + # Attribution: the file is named without the bounds qualifier, which is + # only appended when the sweep is what introduced the fault. + assert f'in {faulty}:' in message + + +@pytest.mark.unit +def test_run_inference_validates_reference_config_before_emptying_output(monkeypatch, tmp_path): + """``run_inference`` validates the reference config before it empties the + study output folder and before it generates any initial design. Re-running + a finished study with a typo'd parameter name must cost the user neither + simulation time nor the previous study's results. + """ + config = { + 'output': 'unit_inference', + 'logging': 'INFO', + 'n_workers': 1, + 'ref_config': BASE_CONFIG, + 'n_steps': 1, + 'kernel': 'MAT3/2', + 'acqf': 'LogEI', + 'seed': 1, + 'observables': {'P_surf': 1.0}, + 'parameters': {'planet.mass_tott': [0.7, 3.0]}, + } + # Stand in for a completed earlier study occupying the same output folder. + output_root = tmp_path / 'output' + output_root.mkdir() + previous = output_root / 'init.csv' + previous.write_text('x_0,y\n0.5,1.0\n', encoding='utf-8') + + monkeypatch.setattr( + inference_mod, + 'get_proteus_directories', + lambda _output: {'output': str(output_root), 'proteus': ''}, + ) + # `safe_rm` is deliberately left real: the point of the test is that it + # never runs. + monkeypatch.setattr(inference_mod, 'setup_logger', lambda **_kwargs: None) + monkeypatch.setattr(inference_mod, 'str_time', lambda: '2026-04-30 00:00:00 UTC') + monkeypatch.setattr(inference_mod.os, 'cpu_count', lambda: 8) + + create_init_calls: list = [] + monkeypatch.setattr( + inference_mod, 'create_init', lambda *a, **kw: create_init_calls.append((a, kw)) + ) + + with pytest.raises(UnknownConfigKeyError, match='planet.mass_tott'): + inference_mod.run_inference(config) + # Ordering: the guard must fire before the initial design is generated. + assert create_init_calls == [] + # ...and before the output folder is emptied. A guard placed after the + # `safe_rm` call would leave this file deleted. + assert previous.read_text(encoding='utf-8') == 'x_0,y\n0.5,1.0\n' + # Nothing downstream of the guard may have run at all. + assert not (output_root / 'ref_config.toml').exists() + + # ============================================================================ # Regression: no stray prints + docstring uses current schema # ============================================================================ diff --git a/tests/inference/test_objective.py b/tests/inference/test_objective.py index 917291ac1..bc7105825 100644 --- a/tests/inference/test_objective.py +++ b/tests/inference/test_objective.py @@ -8,6 +8,7 @@ from __future__ import annotations +import logging import subprocess import pandas as pd @@ -21,6 +22,7 @@ pytest.importorskip('botorch') pytest.importorskip('gpytorch') +import proteus.inference.failures as failures_mod # noqa: E402 import proteus.inference.objective as objective_mod # noqa: E402 pytestmark = [pytest.mark.unit, pytest.mark.timeout(30)] @@ -79,6 +81,32 @@ def test_update_toml_updates_nested_keys(tmp_path): assert loaded['new']['branch']['leaf'] == 3 +@pytest.mark.unit +def test_apply_nested_updates_mutates_in_place_and_rejects_value_paths(): + """``apply_nested_updates`` writes dotted keys into the dict it was given, + creating the sections a new key needs, and refuses a path that descends + through an entry holding a value. The refusal matters because a swept + parameter name is user-supplied: ``planet.mass_tot.value`` would otherwise + fail with an attribute error naming nothing the user wrote. + """ + config = {'section': {'value': 1}} + returned = objective_mod.apply_nested_updates( + config, {'section.value': 2, 'new.branch.leaf': 3} + ) + assert config['section']['value'] == 2 + assert config['new']['branch']['leaf'] == 3 + # In-place: the same object is handed back, so a caller holding the + # original reference sees the updates. + assert returned is config + + with pytest.raises(ValueError, match="'section.value' holds a value"): + objective_mod.apply_nested_updates(config, {'section.value.deeper': 4}) + # The refused key is not written. Updates are applied as they are walked, + # so an earlier key in the same call would already have been applied; this + # pins only that the rejected one was not. + assert config['section']['value'] == 2 + + @pytest.mark.unit def test_run_proteus_success_handles_escaped_atmosphere(monkeypatch, tmp_path): """``run_proteus`` handles the escaped-atmosphere case (P_surf=0): @@ -118,7 +146,11 @@ def test_run_proteus_success_handles_escaped_atmosphere(monkeypatch, tmp_path): assert obs['P_surf'] == pytest.approx(0.0) assert obs['atm_kg_per_mol'] == pytest.approx(0.0) assert len(updates) == 2 - assert status == 20 + # No status file was written, which is reported as such rather than as a + # generic error: a run that dies during start-up and a run that reaches + # the main loop and fails there call for different investigations. + assert status == objective_mod.STATUS_MISSING + assert status != 20 @pytest.mark.unit @@ -164,40 +196,71 @@ def _fake_run(*args, **kwargs): @pytest.mark.unit def test_run_proteus_raises_when_command_fails(monkeypatch, tmp_path): - """A non-zero exit from the proteus binary is wrapped as - ``RuntimeError`` with an 'exit code N' message; the exit code is - surfaced so the caller can diagnose the failure mode. + """A non-zero exit from the proteus binary is reported as a + ``ProteusRunFailure`` naming the run, its exit code, and the status the + simulator recorded for itself, so the failure mode can be diagnosed + without opening the study by hand. """ out_abs = tmp_path / 'sim' out_abs.mkdir(parents=True) + # The simulator recorded an atmosphere-model error before exiting. The + # report must carry this, not a code inferred from the exit status. + (out_abs / 'status').write_text('22\nError (Atmosphere model)\n', encoding='utf-8') monkeypatch.setattr( objective_mod, 'get_proteus_directories', lambda _path: {'output': str(out_abs)} ) monkeypatch.setattr(objective_mod, 'update_toml', lambda *_args, **_kwargs: None) - monkeypatch.setattr( - objective_mod.subprocess, - 'run', - lambda *args, **kwargs: (_ for _ in ()).throw( - subprocess.CalledProcessError(returncode=3, cmd=['proteus']) - ), - ) - with pytest.raises(RuntimeError, match='exit code 3') as excinfo: + def _fake_run(*_args, **kwargs): + # The real simulator writes to the stream it is handed before it dies. + kwargs['stdout'].write('boom\n') + kwargs['stdout'].flush() + raise subprocess.CalledProcessError(returncode=3, cmd=['proteus']) + + monkeypatch.setattr(objective_mod.subprocess, 'run', _fake_run) + + with pytest.raises(objective_mod.ProteusRunFailure) as excinfo: objective_mod.run_proteus( - parameters={}, + parameters={'planet.mass_tot': 1.25}, worker=0, iter=0, observables=['P_surf'], ref_config='reference.toml', output='dummy_output', ) + failure = excinfo.value # Cause-preservation guard: the original CalledProcessError must be # chained via __cause__ so the operator sees the failing command. - assert isinstance(excinfo.value.__cause__, subprocess.CalledProcessError) + assert isinstance(failure.__cause__, subprocess.CalledProcessError) # Exit-code-fidelity guard: a regression that always reported # 'exit code 0' or hardcoded a different code would still pass a # plain regex match if loose, so pin the integer through the cause. - assert excinfo.value.__cause__.returncode == 3 + assert failure.__cause__.returncode == 3 + assert failure.exit_code == 3 + # Status fidelity: the status file is read on the failure path. A + # regression that raised before reading it would report the missing + # sentinel, and one that kept the old hard-coded fallback would report 20. + assert failure.status == 22 + assert 'Atmosphere' in failure.status_desc + # The swept parameter is named; the fixed per-run overrides are not, + # because they carry no information about which sample failed. + assert failure.parameters == {'planet.mass_tot': pytest.approx(1.25)} + assert 'params.out.path' not in failure.parameters + # The capture is kept beside the run folder, not inside it: the simulator + # empties its own output directory once it starts, which would unlink a + # file held open there. + console = out_abs.parent / f'{out_abs.name}{objective_mod.CHILD_CONSOLE_SUFFIX}' + assert console.is_file() + assert 'boom' in console.read_text(encoding='utf-8') + assert not (out_abs / console.name).exists() + # The failure names that capture rather than copying its contents. A run + # that dies before its own logger exists leaves nothing else to read, so a + # report that named no path would leave the cause unreachable. + assert failure.console_path == str(console) + rendered = failure.report() + assert 'worker=0 iter=0' in rendered + assert 'planet.mass_tot=1.25' in rendered + assert str(console) in rendered @pytest.mark.unit @@ -245,7 +308,7 @@ def test_run_proteus_raises_on_missing_observable(monkeypatch, tmp_path): output='dummy_output', ) assert obs['P_surf'] == pytest.approx(1.0) - assert status == 20 + assert status == objective_mod.STATUS_MISSING @pytest.mark.unit @@ -368,3 +431,520 @@ def fake_J(x, **kwargs): assert captured['x'][0, 0].item() == pytest.approx(1.0) assert captured['x'][0, 1].item() == pytest.approx(1.5) + + +# ============================================================================ +# Failure reporting for a single simulator run +# ============================================================================ + + +@pytest.mark.unit +def test_run_proteus_failure_distinguishes_a_missing_status_from_a_generic_error( + monkeypatch, tmp_path +): + """A run that dies before writing a status file is reported as having + written none, rather than as a generic configuration error. The two call + for different investigations: the first points at the simulator's start-up + (environment, reference data), the second at the model configuration. + """ + out_abs = tmp_path / 'sim' + out_abs.mkdir(parents=True) + monkeypatch.setattr( + objective_mod, 'get_proteus_directories', lambda _path: {'output': str(out_abs)} + ) + monkeypatch.setattr(objective_mod, 'update_toml', lambda *_args, **_kwargs: None) + + def _fake_run(*_args, **kwargs): + kwargs['stdout'].write('Error: no\n') + kwargs['stdout'].flush() + raise subprocess.CalledProcessError(returncode=1, cmd=['proteus']) + + monkeypatch.setattr(objective_mod.subprocess, 'run', _fake_run) + + with pytest.raises(objective_mod.ProteusRunFailure) as excinfo: + objective_mod.run_proteus( + parameters={}, + worker=3, + iter=4, + observables=['P_surf'], + ref_config='reference.toml', + output='dummy_output', + ) + failure = excinfo.value + assert failure.status == objective_mod.STATUS_MISSING + assert 'no readable status file' in failure.status_desc + # Discrimination: the previous behaviour reported code 20 for this case, + # which reads as a configuration fault the user does not have. + assert failure.status != 20 + assert 'Generic' not in failure.status_desc + # No logfile exists either, so the report must not invent one. + assert failure.log_path is None + assert 'logfile' not in failure.report() + + # Edge case: the same run with a status file present reports that status, + # which proves the sentinel above came from the absent file and not from a + # reader that always fails. + (out_abs / 'status').write_text('21\nError (Interior model)\n', encoding='utf-8') + with pytest.raises(objective_mod.ProteusRunFailure) as excinfo: + objective_mod.run_proteus( + parameters={}, + worker=3, + iter=4, + observables=['P_surf'], + ref_config='reference.toml', + output='dummy_output', + ) + assert excinfo.value.status == 21 + + +@pytest.mark.unit +def test_run_proteus_failure_points_at_the_simulator_logfile(monkeypatch, tmp_path): + """When the failed run left a logfile, the report names it. That file holds + the traceback the simulator captured for itself, and is the only place the + cause of a mid-run crash is recorded. + """ + out_abs = tmp_path / 'sim' + out_abs.mkdir(parents=True) + (out_abs / 'proteus_00.log').write_text('early\n', encoding='utf-8') + (out_abs / 'proteus_01.log').write_text('CRITICAL Uncaught exception\n', encoding='utf-8') + monkeypatch.setattr( + objective_mod, 'get_proteus_directories', lambda _path: {'output': str(out_abs)} + ) + monkeypatch.setattr(objective_mod, 'update_toml', lambda *_args, **_kwargs: None) + monkeypatch.setattr( + objective_mod.subprocess, + 'run', + lambda *args, **kwargs: (_ for _ in ()).throw( + subprocess.CalledProcessError(returncode=1, cmd=['proteus']) + ), + ) + + with pytest.raises(objective_mod.ProteusRunFailure) as excinfo: + objective_mod.run_proteus( + parameters={}, + worker=0, + iter=0, + observables=['P_surf'], + ref_config='reference.toml', + output='dummy_output', + ) + # The newest logfile is the one the failed run wrote; an earlier one + # belongs to a previous attempt in the same folder. + assert excinfo.value.log_path.endswith('proteus_01.log') + assert 'proteus_01.log' in excinfo.value.report() + + +@pytest.mark.unit +def test_run_proteus_reports_a_clean_exit_that_produced_no_output(monkeypatch, tmp_path): + """A run that exits zero but writes no readable helpfile is reported as a + failed sample rather than crashing the study with a bare parser error. The + exit code is recorded as zero so the report does not suggest a crash. + """ + out_abs = tmp_path / 'sim' + out_abs.mkdir(parents=True) + monkeypatch.setattr( + objective_mod, 'get_proteus_directories', lambda _path: {'output': str(out_abs)} + ) + monkeypatch.setattr(objective_mod, 'update_toml', lambda *_args, **_kwargs: None) + monkeypatch.setattr(objective_mod.subprocess, 'run', lambda *args, **kwargs: None) + + # No helpfile at all. + with pytest.raises(objective_mod.ProteusRunFailure) as excinfo: + objective_mod.run_proteus( + parameters={}, + worker=0, + iter=0, + observables=['P_surf'], + ref_config='reference.toml', + output='dummy_output', + ) + assert excinfo.value.exit_code == 0 + assert 'no readable output' in excinfo.value.reason + + # Edge case: a helpfile that exists but holds no rows. + (out_abs / 'runtime_helpfile.csv').write_text('', encoding='utf-8') + with pytest.raises(objective_mod.ProteusRunFailure): + objective_mod.run_proteus( + parameters={}, + worker=0, + iter=0, + observables=['P_surf'], + ref_config='reference.toml', + output='dummy_output', + ) + + # Discrimination: a helpfile with a usable row completes normally, so the + # two failures above come from the output and not from an unconditional + # raise on this code path. + pd.DataFrame([{'P_surf': 2.5}]).to_csv( + out_abs / 'runtime_helpfile.csv', sep=' ', index=False + ) + obs, _status = objective_mod.run_proteus( + parameters={}, + worker=0, + iter=0, + observables=['P_surf'], + ref_config='reference.toml', + output='dummy_output', + ) + assert obs['P_surf'] == pytest.approx(2.5) + + +@pytest.mark.unit +def test_J_scores_a_failed_run_badly_and_keeps_the_study_running(monkeypatch, tmp_path, caplog): + """A parameter combination the simulator cannot integrate is scored as a + poor sample so the sweep continues, and the failure is reported once in + full and recorded for the end-of-study tally. Aborting instead would end a + study on the first unphysical corner of the parameter box. + """ + monkeypatch.setattr( + objective_mod, 'get_proteus_directories', lambda _path: {'output': str(tmp_path)} + ) + failure = objective_mod.ProteusRunFailure( + reason='the simulator exited with an error', + worker=1, + iter=2, + out_dir='/study/workers/w_1/i_2', + exit_code=1, + status=21, + parameters={'planet.mass_tot': 3.0}, + ) + + def _fail(**_kwargs): + raise failure + + monkeypatch.setattr(objective_mod, 'run_proteus', _fail) + monkeypatch.setenv(failures_mod.ABORT_ON_FAILURE_ENV, '0') + + with caplog.at_level('WARNING'): + value = objective_mod.J( + x=torch.tensor([[0.5]], dtype=torch.double), + parameters=['planet.mass_tot'], + true_observables={'P_surf': 1.0}, + worker=1, + iter=2, + output='dummy_output', + ref_config='reference.toml', + ) + + assert value.shape == (1, 1) + assert value.item() == pytest.approx(objective_mod.BAD_OBJ_VALUE) + # The score must be far below any value a successful run can produce, or + # the optimiser would be drawn toward the region that fails. + assert value.item() < -10.0 + # Reported once, in full: the status description and the output folder are + # what let the user find the run. + reported = '\n'.join(record.getMessage() for record in caplog.records) + assert 'Interior model' in reported + assert '/study/workers/w_1/i_2' in reported + + # The same failure is left on disk for the end-of-study tally, because a + # log line scrolls past and a study that failed mostly needs a count. + recorded = failures_mod.read_failure_records(tmp_path) + assert [(r['worker'], r['iter'], r['status']) for r in recorded] == [(1, 2, 21)] + assert recorded[0]['planet.mass_tot'] == pytest.approx(3.0) + + # Opting in turns the same failure into a hard stop; monkeypatch restores + # the variable afterwards. + monkeypatch.setenv(failures_mod.ABORT_ON_FAILURE_ENV, '1') + with pytest.raises(objective_mod.ProteusRunFailure): + objective_mod.J( + x=torch.tensor([[0.5]], dtype=torch.double), + parameters=['planet.mass_tot'], + true_observables={'P_surf': 1.0}, + worker=1, + iter=2, + output='dummy_output', + ref_config='reference.toml', + ) + + +@pytest.mark.unit +def test_J_scores_a_clean_run_that_stopped_in_an_error_state(monkeypatch, tmp_path, caplog): + """A run that exits cleanly but records an error status is scored badly and + named in the log. Status 25 is the only error code reachable this way: it + is written when a run is stopped through its keepalive file, and the + simulator then terminates normally. + + 'R_obs' is used as the observable because it is compared linearly, which + gives the exact-match objective a closed form to pin against. + """ + monkeypatch.setattr( + objective_mod, 'get_proteus_directories', lambda _path: {'output': str(tmp_path)} + ) + monkeypatch.setattr( + objective_mod, + 'run_proteus', + lambda **_kwargs: ({'R_obs': 9.25e6}, 25), + ) + monkeypatch.setenv(failures_mod.ABORT_ON_FAILURE_ENV, '0') + + with caplog.at_level('WARNING'): + value = objective_mod.J( + x=torch.tensor([[0.5]], dtype=torch.double), + parameters=['planet.mass_tot'], + true_observables={'R_obs': 9.25e6}, + worker=0, + iter=0, + output='dummy_output', + ref_config='reference.toml', + ) + assert value.item() == pytest.approx(objective_mod.BAD_OBJ_VALUE) + assert 'status 25' in '\n'.join(r.getMessage() for r in caplog.records) + # Counted in the end-of-study tally alongside the runs that crashed. A + # tally that covered only crashes would understate a study stopped by hand. + recorded = failures_mod.read_failure_records(tmp_path) + assert [r['status'] for r in recorded] == [25] + assert recorded[0]['exit_code'] == 0 + + # Discrimination: the same observables under a completed status (13, + # "target time reached") are scored normally, which rules out a regression + # that returns the failure score for every run. + monkeypatch.setattr( + objective_mod, + 'run_proteus', + lambda **_kwargs: ({'R_obs': 9.25e6}, 13), + ) + good = objective_mod.J( + x=torch.tensor([[0.5]], dtype=torch.double), + parameters=['planet.mass_tot'], + true_observables={'R_obs': 9.25e6}, + worker=0, + iter=0, + output='dummy_output', + ref_config='reference.toml', + failure_codes=[], + ) + # Closed form for an exact match on a linear observable: the normalised + # difference is zero, so sq_dist is zero and the score is + # -log10(0 + EPS_CLIP) = -log10(1e-10) = 10. + assert good.item() == pytest.approx(10.0, rel=1e-9) + # Sign guard: a flipped objective would land at -10, which is still above + # BAD_OBJ_VALUE and would pass a bare "better than failure" assertion. + assert good.item() > 0 + # Scale guard: the failure score is -20, so the two are far apart. + assert good.item() - objective_mod.BAD_OBJ_VALUE > 25.0 + + +@pytest.mark.unit +def test_J_aborts_on_a_clean_run_that_stopped_in_an_error_state(monkeypatch, tmp_path): + """`abort_on_failure` stops the study on a run that exited cleanly but + recorded an error status, the same way it stops on a run that crashed. + Both are faults; only the route by which the simulator reported them + differs, so honouring the setting on one and not the other would let a + study set up with `abort_on_failure = true` run to completion on a + reference config that fails every evaluation. + + The asymmetry the setting must keep: an excluded status completed + normally, so it is scored as a poor sample and the study carries on even + with aborting enabled. + """ + monkeypatch.setattr( + objective_mod, 'get_proteus_directories', lambda _path: {'output': str(tmp_path)} + ) + + def _run(status, worker, iter, codes=()): + monkeypatch.setattr( + objective_mod, + 'run_proteus', + lambda **_kwargs: ({'R_obs': 9.25e6}, status), + ) + return objective_mod.J( + x=torch.tensor([[0.5]], dtype=torch.double), + parameters=['planet.mass_tot'], + true_observables={'R_obs': 9.25e6}, + worker=worker, + iter=iter, + output='dummy_output', + ref_config='reference.toml', + failure_codes=list(codes), + ) + + monkeypatch.setenv(failures_mod.ABORT_ON_FAILURE_ENV, '1') + + # Status 25: written when a run is stopped through its keepalive file, so + # the simulator exits 0 and the fault is visible only in the status file. + with pytest.raises(objective_mod.ProteusRunFailure) as caught: + _run(25, worker=0, iter=0) + assert caught.value.status == 25 + assert caught.value.category == objective_mod.CATEGORY_FAILURE + # Exit code 0 is the whole point of this path: the abort must not depend + # on the child having exited non-zero. + assert caught.value.exit_code == 0 + + # Boundary of the failure set: STATUS_MISSING is the lowest code treated + # as a fault, and the run's own account of itself is absent, so it cannot + # be scored. A range check written as `20 <= status <= 28` alone would + # miss it. + with pytest.raises(objective_mod.ProteusRunFailure) as missing: + _run(objective_mod.STATUS_MISSING, worker=0, iter=1) + assert missing.value.status == objective_mod.STATUS_MISSING + + # The record is written before the abort, so an aborted study still says + # on disk what stopped it rather than leaving only the traceback. + recorded = failures_mod.read_failure_records(tmp_path) + # Ordered by (worker, iter), so the status-25 run at iter 0 comes first. + assert [r['status'] for r in recorded] == [25, objective_mod.STATUS_MISSING] + + # Discrimination against a fix that aborts on `failed or excluded`: an + # excluded status is scored as a poor sample and returns normally. + excluded = _run(11, worker=1, iter=0, codes=(11,)) + assert excluded.item() == pytest.approx(objective_mod.BAD_OBJ_VALUE) + # Boundedness: the failure score sits far below anything a completed run + # can reach, so the optimiser is not drawn toward the excluded region. + assert excluded.item() < -10.0 + assert failures_mod.read_failure_records(tmp_path)[-1]['category'] == ( + objective_mod.CATEGORY_EXCLUDED + ) + + # Discrimination against a regression that raises unconditionally: with + # the setting off, the same error status is scored and the study goes on. + monkeypatch.setenv(failures_mod.ABORT_ON_FAILURE_ENV, '0') + scored = _run(25, worker=2, iter=0) + assert scored.item() == pytest.approx(objective_mod.BAD_OBJ_VALUE) + assert scored.item() < -10.0 + + +@pytest.mark.unit +def test_J_treats_the_documented_error_codes_as_failures(monkeypatch, tmp_path): + """The failure range covers the error statuses the simulator can record. + Code 28 is the highest error the status table defines; 29 is a completion + ('planet evaporated') and no current code path writes it, so it must not + be scored as a failure by an off-by-one in the range bound. + """ + monkeypatch.setenv(failures_mod.ABORT_ON_FAILURE_ENV, '0') + monkeypatch.setattr( + objective_mod, 'get_proteus_directories', lambda _path: {'output': str(tmp_path)} + ) + + def _score(status): + monkeypatch.setattr( + objective_mod, + 'run_proteus', + lambda **_kwargs: ({'R_obs': 9.25e6}, status), + ) + return objective_mod.J( + x=torch.tensor([[0.5]], dtype=torch.double), + parameters=['planet.mass_tot'], + true_observables={'R_obs': 9.25e6}, + worker=0, + iter=0, + output='dummy_output', + ref_config='reference.toml', + ).item() + + # Highest defined error code, and the escape-model error below it. + assert _score(28) == pytest.approx(objective_mod.BAD_OBJ_VALUE) + assert _score(21) == pytest.approx(objective_mod.BAD_OBJ_VALUE) + # Completion codes are scored on their observables. + assert _score(29) == pytest.approx(10.0, rel=1e-9) + assert _score(13) == pytest.approx(10.0, rel=1e-9) + # A run that never updated its status past 'Running' died mid-flight. + assert _score(1) == pytest.approx(objective_mod.BAD_OBJ_VALUE) + # An unreadable status file is treated as a failure, because the run's own + # account of itself is missing and its output cannot be trusted. + assert _score(objective_mod.STATUS_MISSING) == pytest.approx(objective_mod.BAD_OBJ_VALUE) + + +@pytest.mark.unit +def test_J_separates_an_excluded_outcome_from_a_failed_run(monkeypatch, tmp_path, caplog): + """A status named in `failure_codes` marks an outcome the study does not fit + against, not a fault. A run stopped by its clock limit (status 11) completed + normally, so it is scored as a poor sample and reported at info level, while + an error status (21, interior model) is reported as a run that produced + nothing usable. Reporting the first as the second sends the user looking for + a bug in a run that did exactly what it was configured to do. + """ + monkeypatch.setenv(failures_mod.ABORT_ON_FAILURE_ENV, '0') + monkeypatch.setattr( + objective_mod, 'get_proteus_directories', lambda _path: {'output': str(tmp_path)} + ) + + def _score(status, worker): + monkeypatch.setattr( + objective_mod, + 'run_proteus', + lambda **_kwargs: ({'R_obs': 9.25e6}, status), + ) + return objective_mod.J( + x=torch.tensor([[0.5]], dtype=torch.double), + parameters=['planet.mass_tot'], + true_observables={'R_obs': 9.25e6}, + worker=worker, + iter=0, + output='dummy_output', + ref_config='reference.toml', + failure_codes=[11], + ).item() + + with caplog.at_level(logging.INFO, logger='fwl.proteus.inference.objective'): + excluded = _score(11, worker=0) + + # The optimiser must still be steered away from the excluded region, so the + # score is the same one a failure carries. + assert excluded == pytest.approx(objective_mod.BAD_OBJ_VALUE) + assert not [r for r in caplog.records if r.levelname in ('WARNING', 'ERROR')] + reported = '\n'.join(r.getMessage() for r in caplog.records) + assert 'excludes' in reported + assert 'maximum clock runtime' in reported + assert 'failure state' not in reported + assert 'failed for worker=0' not in reported + + # The record is kept for the end-of-study tally, labelled so the tally can + # count it apart from the runs that genuinely failed. + recorded = failures_mod.read_failure_records(tmp_path) + assert [(r['status'], r['category']) for r in recorded] == [ + (11, objective_mod.CATEGORY_EXCLUDED) + ] + + # Discrimination: an error status under the same call is still a failure, + # warned about and recorded under the other category. Without this the test + # would pass against a regression that labelled every run 'excluded'. + caplog.clear() + with caplog.at_level(logging.INFO, logger='fwl.proteus.inference.objective'): + failed = _score(21, worker=1) + assert failed == pytest.approx(objective_mod.BAD_OBJ_VALUE) + warnings = [r for r in caplog.records if r.levelname == 'WARNING'] + assert len(warnings) == 1 + assert 'failed for worker=1' in warnings[0].getMessage() + assert 'stopped in a failure state' in warnings[0].getMessage() + assert 'status 21' in warnings[0].getMessage() + recorded = failures_mod.read_failure_records(tmp_path) + assert [(r['status'], r['category']) for r in recorded] == [ + (11, objective_mod.CATEGORY_EXCLUDED), + (21, objective_mod.CATEGORY_FAILURE), + ] + + # Discrimination: a completion status that the study does not exclude is + # scored on its observables and leaves no record at all. The exact match on + # a linear observable has the closed form -log10(0 + 1e-10) = 10. + assert _score(13, worker=2) == pytest.approx(10.0, rel=1e-9) + assert len(failures_mod.read_failure_records(tmp_path)) == 2 + + +# ============================================================================ +# Failure records: written per evaluation, read back for the study summary +# ============================================================================ + + +@pytest.mark.unit +def test_run_output_dir_names_the_folder_the_simulator_is_given(monkeypatch, tmp_path): + """The per-evaluation folder is derived in one place, so the path a failure + report names is the path the simulator was told to write to. Initial + samples use worker -1, which must survive the same construction. + """ + monkeypatch.setattr( + objective_mod, + 'get_proteus_directories', + lambda path: {'output': str(tmp_path / path)}, + ) + + rel, absolute = objective_mod.run_output_dir('study', 2, 7) + assert rel.as_posix() == 'study/workers/w_2/i_7' + assert absolute == tmp_path / 'study' / 'workers' / 'w_2' / 'i_7' + + # Initial sampling identifies itself with worker -1 rather than a worker + # index, and must land in its own folder rather than colliding with w_1. + rel_init, _ = objective_mod.run_output_dir('study', -1, 7) + assert rel_init.as_posix() == 'study/workers/w_-1/i_7' + assert rel_init != rel diff --git a/tests/inference/test_plot.py b/tests/inference/test_plot.py index 542419c75..f914cb194 100644 --- a/tests/inference/test_plot.py +++ b/tests/inference/test_plot.py @@ -585,6 +585,48 @@ def test_plot_result_correlation_multi_par_multi_obs(monkeypatch, tmp_path, capl assert 'Missing helpfile for' in caplog.text +@pytest.mark.unit +def test_plot_result_correlation_ignores_stray_console_log_file(monkeypatch, tmp_path): + """A worker's console-log capture file must not be treated as a case dir. + + Regression for a crash where a stray file such as ``i_0_console.log``, + sitting beside the real ``i_0`` case directory in a worker folder, matched + the ``i_*`` glob used to find cases. ``toml.load`` then received a file + path, not a directory, and raised ``NotADirectoryError`` when the code + appended ``init_coupler.toml`` to it. + """ + workers = tmp_path / 'workers' + case_ok = workers / 'w_-1' / 'i_0' + case_ok.mkdir(parents=True) + (case_ok / 'init_coupler.toml').write_text( + toml.dumps({'planet': {'mass_tot': 1.5}}), + encoding='utf-8', + ) + pd.DataFrame([{'P_surf': 1.0}]).to_csv( + case_ok / 'runtime_helpfile.csv', sep=' ', index=False + ) + + # Sibling capture file that matches the `i_*` glob but is not a case dir. + (workers / 'w_-1' / 'i_0_console.log').write_text('log output\n', encoding='utf-8') + + axis = MagicMock() + axis.__getitem__.return_value = axis + fig = MagicMock() + mock_plt = MagicMock() + mock_plt.subplots.return_value = (fig, axis) + monkeypatch.setattr(plot_mod, 'plt', mock_plt) + monkeypatch.setattr(plot_mod, 'variable_is_logarithmic', lambda _k: False) + + # Must not raise NotADirectoryError from treating the log file as a case. + plot_mod.plot_result_correlation( + pars={'planet.mass_tot': [0.7, 3.0]}, + obs={'P_surf': 1.0}, + directory=str(tmp_path), + ) + + fig.savefig.assert_called_once() + + def test_plot_result_correlation_two_par_two_obs_uses_2d_axes(monkeypatch, tmp_path): """n_par > 1 and n_obs > 1 takes the ``axs[j, i]`` 2D indexing branch. diff --git a/tests/inference/test_transforms.py b/tests/inference/test_transforms.py index 02cc44dae..d9b3a5435 100644 --- a/tests/inference/test_transforms.py +++ b/tests/inference/test_transforms.py @@ -345,11 +345,12 @@ def test_set_child_timeout_stores_in_env(monkeypatch): def test_run_proteus_wraps_timeout_as_runtime_error(monkeypatch, tmp_path): - """subprocess.TimeoutExpired is wrapped as RuntimeError with a 'timed out' - message so the inference harness receives a consistent error type. + """A run that exceeds its time limit is reported as a ProteusRunFailure + naming the limit, so the harness receives one error type for every fault + that is specific to a single run. Discrimination: a regression that re-raised the raw TimeoutExpired would - break the except-RuntimeError handler in the BO worker loop. + escape the handler in the objective wrapper and kill the worker. """ import subprocess @@ -365,7 +366,7 @@ def _fake_run(*args, **kwargs): monkeypatch.setattr(obj_mod.subprocess, 'run', _fake_run) - with pytest.raises(RuntimeError, match='timed out') as exc_info: + with pytest.raises(obj_mod.ProteusRunFailure, match='timeout') as exc_info: obj_mod.run_proteus( parameters={}, worker=0, @@ -375,6 +376,12 @@ def _fake_run(*args, **kwargs): output='dummy_output', ) assert isinstance(exc_info.value.__cause__, subprocess.TimeoutExpired) + # A wedged run never returns an exit code, so the report must omit it + # rather than invent one that would read as a crash. + assert exc_info.value.exit_code is None + # The failure stays a RuntimeError, which is what the surrounding code + # and any existing caller catches. + assert isinstance(exc_info.value, RuntimeError) # -------------------------------------------------------------------------- diff --git a/tests/inference/test_utils_branches.py b/tests/inference/test_utils_branches.py index 2c6b3e675..2ada8a980 100644 --- a/tests/inference/test_utils_branches.py +++ b/tests/inference/test_utils_branches.py @@ -294,3 +294,70 @@ def test_get_kernel_raises_for_unknown_kernel_name(): # Edge: case-sensitive — 'rbf' is not 'RBF'. with pytest.raises(ValueError, match='Unknown kernel'): get_kernel('rbf', d=2) + + +# --------------------------------------------------------------------------- +# Accounting for the evaluations that failed +# --------------------------------------------------------------------------- + + +@pytest.mark.unit +def test_print_results_counts_unscored_runs_and_refuses_a_study_with_no_fit(tmp_path, caplog): + """Evaluations that failed, and those that completed on an excluded status, + both carry the failure score rather than a fit quality, so the summary says + how many of them there were. The objective value alone cannot tell the two + apart, so the wording covers both. When no optimisation evaluation produced + a fit quality there is no best fit at all, and the summary stops rather than + reporting the least-bad run as an inference result. + """ + from proteus.inference.objective import BAD_OBJ_VALUE + from proteus.inference.utils import print_results + + _make_worker_dir(tmp_path, worker=0, iteration=0, obs_value=0.1, param_value=0.5) + _make_worker_dir(tmp_path, worker=0, iteration=1, obs_value=0.9, param_value=1.0) + best_dir = _make_worker_dir(tmp_path, worker=0, iteration=2, obs_value=0.5, param_value=1.5) + + logs = [ + {'worker': 0, 'task_id': 0}, + {'worker': 0, 'task_id': 1}, + {'worker': 0, 'task_id': 2}, + ] + config = { + 'observables': {'H2O_vmr': 0.9}, + 'parameters': {'planet.mass_tot': [0.5, 1.5]}, + } + + # One of the two optimisation evaluations failed; the other is still the + # best fit and must be reported normally. + D = { + 'X': torch.tensor([[0.0], [1.0], [0.5]]), + 'Y': torch.tensor([[-1.0], [BAD_OBJ_VALUE], [2.0]]), + } + with caplog.at_level(logging.WARNING, logger='fwl.proteus.inference.utils'): + result = print_results(D, logs, config, str(tmp_path), n_init=1) + assert str(best_dir / 'init_coupler.toml') == str(result) + assert any( + '1 of 2 optimisation evaluations carry the failure score' in r.message + for r in caplog.records + ) + + # Discrimination: the same study with no failure score present reports no + # count, so the message above tracks the data and is not emitted always. + caplog.clear() + D_clean = { + 'X': torch.tensor([[0.0], [1.0], [0.5]]), + 'Y': torch.tensor([[-1.0], [1.0], [2.0]]), + } + with caplog.at_level(logging.WARNING, logger='fwl.proteus.inference.utils'): + print_results(D_clean, logs, config, str(tmp_path), n_init=1) + assert not [r for r in caplog.records if 'carry the failure score' in r.message] + + # No optimisation evaluation produced a fit quality: nothing to report. + D_dead = { + 'X': torch.tensor([[0.0], [1.0], [0.5]]), + 'Y': torch.tensor([[-1.0], [BAD_OBJ_VALUE], [BAD_OBJ_VALUE]]), + } + with pytest.raises( + RuntimeError, match='None of the 2 optimisation evaluations produced a fit quality' + ): + print_results(D_dead, logs, config, str(tmp_path), n_init=1) diff --git a/tests/test_cli.py b/tests/test_cli.py index 246f45fc6..eedbdf508 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -3,6 +3,7 @@ import builtins import importlib.util +import logging import sys from pathlib import Path @@ -562,14 +563,27 @@ def fake_download_melting_curves(configuration, clean: bool = False): assert not any(c[0] == 'zalmoxis_eos' for c in calls) +def assert_refusal_logged_as_error(caplog, key: str) -> None: + """Check that a config refusal named `key` was logged at ERROR, not below. + + The refusal reaches the terminal through the 'fwl' logger rather than + click's own stream, so the captured records are what pins it. The level is + asserted as well as the text: a refusal emitted at INFO or WARNING carries + the same words and would otherwise pass. + """ + named = [rec for rec in caplog.records if key in rec.getMessage()] + assert named, f'no log record named {key}' + assert [rec.levelno for rec in named] == [logging.ERROR] * len(named) + + @pytest.mark.unit -def test_get_interiordata_reports_an_unknown_config_key_cleanly(monkeypatch, tmp_path): +def test_get_interiordata_reports_an_unknown_config_key_cleanly(monkeypatch, tmp_path, caplog): """A misspelled key stops the download and is reported as a CLI error. The download commands act on the configuration, so acting on one whose keys were silently discarded would fetch data for a setup the user did not ask - for. The failure has to arrive in the CLI's own error style with the key - named, not as a traceback. + for. The failure has to arrive at error level with the key named, not as a + traceback. """ import tomllib @@ -594,10 +608,11 @@ def test_get_interiordata_reports_an_unknown_config_key_cleanly(monkeypatch, tmp with open(cfg, 'w') as f: tomlkit.dump(raw, f) - res = runner.invoke(cli.cli, ['get', 'interiordata', '--config-path', str(cfg)]) + with caplog.at_level(logging.INFO, logger='fwl'): + res = runner.invoke(cli.cli, ['get', 'interiordata', '--config-path', str(cfg)]) assert res.exit_code != 0 - assert 'planet.mass_total' in res.output - # A ClickException prints "Error: ..." and does not surface a traceback. + assert_refusal_logged_as_error(caplog, 'planet.mass_total') + # A ClickException does not surface a traceback. assert 'Traceback' not in res.output # The config-dependent download is not reached; the config-independent one # ahead of it may already have run, which is why only the former is pinned. @@ -1196,11 +1211,12 @@ def fake_grid_from_config(path, test_run=False): assert received[0][1] is False -def test_start_reports_an_unknown_config_key_cleanly(tmp_path): - """``proteus start`` refuses a misspelled key in the CLI's own error style. +def test_start_reports_an_unknown_config_key_cleanly(tmp_path, caplog): + """``proteus start`` refuses a misspelled key at error level. This is the command most runs go through, so a refusal that arrives as a - bare traceback leaves the name of the offending key buried in it. + bare traceback leaves the name of the offending key buried in it, and one + emitted below error level reads as ordinary progress output. """ import tomllib @@ -1215,9 +1231,10 @@ def test_start_reports_an_unknown_config_key_cleanly(tmp_path): with open(cfg, 'w') as f: tomlkit.dump(raw, f) - res = runner.invoke(cli.cli, ['start', '-c', str(cfg), '--offline']) + with caplog.at_level(logging.INFO, logger='fwl'): + res = runner.invoke(cli.cli, ['start', '-c', str(cfg), '--offline']) assert res.exit_code != 0 - assert 'planet.mass_total' in res.output + assert_refusal_logged_as_error(caplog, 'planet.mass_total') assert 'Traceback' not in res.output @@ -1243,13 +1260,13 @@ def boom(*_args, **_kwargs): assert 'something else went wrong entirely' in str(res.exception) -def test_grid_reports_an_unknown_key_in_the_base_config_cleanly(tmp_path, monkeypatch): - """``proteus grid`` refuses a base config with a misspelled key, in CLI style. +def test_grid_reports_an_unknown_key_in_the_base_config_cleanly(tmp_path, monkeypatch, caplog): + """``proteus grid`` refuses a base config with a misspelled key, at error level. Case config files are written out from the parsed base config, so an unrecognised key in the base never reaches them and the grid would otherwise run every case on a default nobody chose. The refusal has to name - the key and arrive as a CLI error, since the whole ensemble depends on it. + the key and arrive as an error, since the whole ensemble depends on it. """ import tomllib @@ -1283,10 +1300,11 @@ def test_grid_reports_an_unknown_key_in_the_base_config_cleanly(tmp_path, monkey ' values = [0.7]\n' ) - res = runner.invoke(cli.cli, ['grid', '-c', str(grid_toml), '--dry-run']) + with caplog.at_level(logging.INFO, logger='fwl'): + res = runner.invoke(cli.cli, ['grid', '-c', str(grid_toml), '--dry-run']) assert res.exit_code != 0 - assert 'params.dt.maxium' in res.output - # A ClickException prints "Error: ..."; an unwrapped raise prints a traceback. + assert_refusal_logged_as_error(caplog, 'params.dt.maxium') + # An unwrapped raise would print a traceback instead. assert 'Traceback' not in res.output diff --git a/tests/utils/test_logs.py b/tests/utils/test_logs.py index fbdde053b..3a27e5c13 100644 --- a/tests/utils/test_logs.py +++ b/tests/utils/test_logs.py @@ -21,6 +21,7 @@ GetCurrentLogfileIndex, GetLogfilePath, StreamToLogger, + attach_worker_logfile, bootstrap_logger, setup_logger, ) @@ -894,3 +895,108 @@ def test_preserves_directory_path(self): path = GetLogfilePath(dirpath, 42) assert path.startswith(dirpath) assert 'proteus_42.log' in path + + +@pytest.fixture +def clean_fwl_logger(): + """Give a test the 'fwl' logger with no handlers, and restore it after. + + The logger is process-global, so a test that attaches a handler to it + would otherwise leak that handler into every test that runs later. + """ + logger = logging.getLogger('fwl') + saved_handlers, saved_level = list(logger.handlers), logger.level + logger.handlers.clear() + try: + yield logger + finally: + logger.handlers.clear() + logger.handlers.extend(saved_handlers) + logger.setLevel(saved_level) + + +@pytest.mark.unit +def test_attach_worker_logfile_appends_to_an_existing_study_logfile(clean_fwl_logger, tmp_path): + """A worker process with no logging configuration of its own reopens the + study logfile and adds to it. Appending rather than recreating is the + whole contract: `setup_logger` deletes the logfile it opens, so a worker + calling that instead would erase everything the study had logged before + the worker started. + """ + logpath = tmp_path / 'infer.log' + logpath.write_text('[ INFO ] parent wrote this first\n', encoding='utf-8') + + attach_worker_logfile(str(logpath), logging.INFO) + logging.getLogger('fwl.worker').error('worker stopped early') + + for handler in clean_fwl_logger.handlers: + handler.flush() + text = logpath.read_text(encoding='utf-8') + + # The pre-existing content survives: this is the assertion that fails if + # the handler is ever opened in 'w' mode. + assert 'parent wrote this first' in text + assert 'worker stopped early' in text + # Written through the study's file format, so worker lines are not visibly + # different from the parent's. + assert '[ ERROR ] worker stopped early' in text + + +@pytest.mark.unit +def test_attach_worker_logfile_carries_a_traceback_and_respects_the_level( + clean_fwl_logger, tmp_path +): + """The message this exists for is a dying worker's traceback, so the + exception text must reach the file, and a level set above INFO must still + suppress the ordinary INFO chatter that would otherwise bloat the logfile. + """ + logpath = tmp_path / 'infer.log' + attach_worker_logfile(str(logpath), logging.WARNING) + + worker_log = logging.getLogger('fwl.worker') + worker_log.info('routine iteration finished') + try: + raise ValueError('objective evaluation failed') + except ValueError: + worker_log.exception('Worker 3 stopped early') + + for handler in clean_fwl_logger.handlers: + handler.flush() + text = logpath.read_text(encoding='utf-8') + + assert 'Worker 3 stopped early' in text + # The traceback body, not just the message: a handler without exc_info + # support would log the first line and drop the cause. + assert 'ValueError: objective evaluation failed' in text + assert 'Traceback (most recent call last)' in text + # Boundary of the configured level: INFO sits one step below WARNING and + # must be dropped, which also rules out a handler left at level NOTSET. + assert 'routine iteration finished' not in text + + +@pytest.mark.unit +def test_attach_worker_logfile_leaves_an_already_configured_logger_alone( + clean_fwl_logger, tmp_path +): + """Under the 'fork' start method a worker inherits the parent's handlers. + Adding a second one there would write every worker line to the logfile + twice, so the call must be a no-op whenever handlers already exist. + """ + inherited = tmp_path / 'inherited.log' + handler = logging.FileHandler(inherited) + handler.setFormatter(logging.Formatter('[ %(levelname)-5s ] %(message)s')) + clean_fwl_logger.addHandler(handler) + clean_fwl_logger.setLevel(logging.INFO) + + untouched = tmp_path / 'should_not_be_written.log' + attach_worker_logfile(str(untouched), logging.INFO) + + assert len(clean_fwl_logger.handlers) == 1 + # The second path is never opened, so no stray logfile appears beside the + # study's own. + assert not untouched.exists() + + logging.getLogger('fwl.worker').warning('one line only') + handler.flush() + # Exactly one copy: a duplicate handler would give two. + assert inherited.read_text(encoding='utf-8').count('one line only') == 1