diff --git a/tvbo/__init__.py b/tvbo/__init__.py index b0b269cc..2f6471df 100644 --- a/tvbo/__init__.py +++ b/tvbo/__init__.py @@ -35,7 +35,23 @@ tempdir = os.path.join(tempfile.gettempdir(), "tvbo") os.makedirs(tempdir, exist_ok=True) -logging.disable(logging.CRITICAL) +# Central logging. Importing tvbo installs only a NullHandler on the ``tvbo`` +# logger, so the package is silent as a library; entry points (``tvbo run``, +# ``SimulationExperiment.run``) surface progress via ``configure_logging`` and +# everything is controlled by one switch (``TVBO_LOG_LEVEL`` / ``set_log_level``). +# This replaces a former process-wide ``logging.disable(CRITICAL)`` that muted +# every logger — see :mod:`tvbo.log`. +from tvbo.log import ( # noqa: E402,F401 + configure_logging, + ensure_configured, + get_log_level, + log_level, + set_log_level, + silence, +) + +if os.environ.get("TVBO_LOG_LEVEL"): + configure_logging() __authors__ = [ "Leon K. Martin", diff --git a/tvbo/adapters/julia.py b/tvbo/adapters/julia.py index 201adb73..0804f9fb 100644 --- a/tvbo/adapters/julia.py +++ b/tvbo/adapters/julia.py @@ -8,9 +8,12 @@ will install Julia (if needed) and all declared packages. """ +import logging import re from typing import Any, Optional +logger = logging.getLogger(__name__) + _julia_main = None _installed_packages = set() @@ -60,16 +63,16 @@ def install_julia_package(package_name: str, Main: Optional[Any] = None, update: if package_name in _installed_packages and not update: return - print(f"{'Updating' if update else 'Installing'} Julia package: {package_name}...") + logger.info("%s Julia package: %s...", "Updating" if update else "Installing", package_name) try: if update: Main.seval(f'import Pkg; Pkg.update("{package_name}")') else: Main.seval(f'import Pkg; Pkg.add("{package_name}")') _installed_packages.add(package_name) - print(f"Successfully {'updated' if update else 'installed'} {package_name}") + logger.info("Successfully %s %s", "updated" if update else "installed", package_name) except Exception as e: - print(f"Warning: Failed to {'update' if update else 'install'} {package_name}: {e}") + logger.warning("Failed to %s %s: %s", "update" if update else "install", package_name, e) raise @@ -91,7 +94,7 @@ def eval_with_auto_install(code, max_retries=3): # Retry after installing continue except Exception: - print(f"Failed to auto-install {package_name}, re-raising original error") + logger.warning("Failed to auto-install %s, re-raising original error", package_name) raise e else: # Not a package error or max retries reached diff --git a/tvbo/classes/atlas.py b/tvbo/classes/atlas.py index 0aa5918a..3661c3e8 100644 --- a/tvbo/classes/atlas.py +++ b/tvbo/classes/atlas.py @@ -6,6 +6,7 @@ produce ranked (relabelled) parcellation volumes from FreeSurfer segmentations. """ +import logging import os try: @@ -63,6 +64,7 @@ def tqdm(x, **kwargs): ] available_atlases = bids_utils.get_unique_entity_values(atlas_data, "atlas") +logger = logging.getLogger(__name__) class Atlas(tvbo_datamodel.BrainAtlas): @@ -258,7 +260,7 @@ def centers(self): except ImportError: centers = [] lookup_labels = [] - print( + logger.warning( "nilearn is required to compute atlas region centers. " "Setting to empty. Install nilearn or provide atlas metadata." ) diff --git a/tvbo/classes/dynamics.py b/tvbo/classes/dynamics.py index 83c91f4d..13944236 100644 --- a/tvbo/classes/dynamics.py +++ b/tvbo/classes/dynamics.py @@ -16,6 +16,7 @@ class that augments the generated LinkML `Dynamics` datamodel with model together with the `Model` and `Dynamics` convenience subclasses. """ +import logging import copy as _copy import functools import os @@ -46,6 +47,8 @@ class that augments the generated LinkML `Dynamics` datamodel with model from tvbo.parse.expression import parse_eq from tvbo.utils import report +logger = logging.getLogger(__name__) + TEMPLATES = templates.root @functools.cache @@ -425,7 +428,7 @@ def update_parameters(metadata, ontoclass, verbose=0, only_used=True, **kwargs): synonym in metadata.parameters for synonym in k.synonym + k.symbol ): if verbose > 0: - print(f"using parameter {label} from the ontology") + logger.debug("using parameter %s from the ontology", label) metadata.parameters.update( { label: tvbo_datamodel.Parameter( diff --git a/tvbo/classes/equation.py b/tvbo/classes/equation.py index 6c384f04..ae977700 100644 --- a/tvbo/classes/equation.py +++ b/tvbo/classes/equation.py @@ -10,6 +10,7 @@ # Handling Equations and Expressions """ +import logging import re from collections import deque @@ -55,6 +56,7 @@ coupling_variables = ["lrc", "short_range_coupling", "coupling", "lc_0", "c_0", "lc_1"] lambda_symbol = sp.symbols("lambda") E = sp.symbols("E") # TODO: not used +logger = logging.getLogger(__name__) def add_spaces_around_operators(expression): @@ -262,8 +264,7 @@ def sympify_value(v, acronym="", evaluate=False): evaluate=False, ) except Exception as e: - print(f"Error parsing equation: {eq}") - print(f"Error message: {e}") + logger.debug("Error parsing equation %r: %s", eq, e) raise ValueError(f"Failed to parse equation: {eq}. Ensure the equation is in a valid format.") return eq @@ -808,7 +809,7 @@ def get_latex_equation(model, func_dict="all", mul_symbol="dot"): if len(search) == 1: c_rhs = search[0] else: - print(search) + logger.debug("ambiguous search for %s in %s: %s", s, model, search) raise ValueError(f"Could not find {s} in {model}") symb = c_rhs.symbol.first() @@ -909,17 +910,17 @@ class and the equation's class in the ontology. Equations that are `None` or for k, v in symbolic_model_equations(model).items(): k_cls = ontology.find_variables(k, model) if k_cls is None: - print('did not find "{}" in "{}"'.format(k, model)) + logger.warning('did not find "%s" in "%s"', k, model) continue # Handle cases where v might be None (e.g., for discrete maps with conditionals) if v is None: - print(f'Skipping "{k}" in "{model}" - equation is None') + logger.debug('Skipping "%s" in "%s" - equation is None', k, model) continue # Check if v has free_symbols attribute (valid SymPy expression) if not hasattr(v, "free_symbols"): - print(f'Skipping "{k}" in "{model}" - not a valid SymPy expression') + logger.debug('Skipping "%s" in "%s" - not a valid SymPy expression', k, model) continue for symbol in v.free_symbols: diff --git a/tvbo/classes/experiment.py b/tvbo/classes/experiment.py index 21a11e82..5c4f0487 100644 --- a/tvbo/classes/experiment.py +++ b/tvbo/classes/experiment.py @@ -56,6 +56,9 @@ from tvbo.utils import traverse_metadata from tvbo.utils import Bunch from tvbo.utils import as_list +from tvbo.log import ensure_configured + +logger = logging.getLogger(__name__) sessionid = 1 @@ -1120,20 +1123,25 @@ def from_bids( # 6. Verify reproducibility if requested # ===================================================================== if run_to_verify and timeseries is not None: - print("Running simulation to verify reproducibility...") + logger.info("Running simulation to verify reproducibility...") ts_rerun = experiment.run(format="jax") # Compare shapes if ts_rerun.shape != timeseries.shape: - print(f"WARNING: Shape mismatch! Loaded: {timeseries.shape}, Rerun: {ts_rerun.shape}") + logger.warning( + "Shape mismatch! Loaded: %s, Rerun: %s", timeseries.shape, ts_rerun.shape + ) else: # Compare data max_diff = np.max(np.abs(np.asarray(ts_rerun.data) - np.asarray(timeseries.data))) if max_diff < 1e-6: - print(f"✓ Verification passed! Max difference: {max_diff:.2e}") + logger.info("Verification passed! Max difference: %.2e", max_diff) else: - print(f"⚠ Data differs. Max difference: {max_diff:.2e}") - print(" This may be expected if noise was used or parameters differ.") + logger.warning( + "Data differs. Max difference: %.2e " + "(may be expected if noise was used or parameters differ).", + max_diff, + ) return experiment, timeseries @@ -1279,8 +1287,7 @@ def noise_sigma_array(self) -> np.ndarray: try: sigma = float(sv.noise.parameters["sigma"].value) except Exception as e: - print(f"Error retrieving sigma for state variable {sv.name}: {e}") - pass + logger.debug("Error retrieving sigma for state variable %s: %s", sv.name, e) if sigma == 0.0: try: @@ -1295,8 +1302,7 @@ def noise_sigma_array(self) -> np.ndarray: ): sigma = float(inparams["sigma"].value) except Exception as e: - print(f"Error retrieving integration-level sigma: {e}") - pass + logger.debug("Error retrieving integration-level sigma: %s", e) sigmas.append(float(sigma)) @@ -1943,6 +1949,12 @@ def run(self, format="tvboptim", initial_conditions=None, results_root=None, **k An `ExperimentResult` holding the integrated time series and any observations, with `source` set to this experiment. """ + # Make tvbo progress visible for interactive/script runs without + # clobbering an app's own logging — the same switch the CLI uses, so + # ``exp.run(...)`` and ``tvbo run`` log identically. No-op if the + # embedding application already configured logging. + ensure_configured() + if "duration" in kwargs: self.integration.duration = kwargs.pop("duration") diff --git a/tvbo/classes/observation.py b/tvbo/classes/observation.py index 274860b7..b526ed29 100644 --- a/tvbo/classes/observation.py +++ b/tvbo/classes/observation.py @@ -8,6 +8,7 @@ callables and curated ontology instances into the underlying datamodel shape. """ +import logging import importlib import inspect from types import FunctionType @@ -34,6 +35,7 @@ from tvbo.codegen.code import render_expression from tvbo.ontology import owl as ontology from tvbo.plot.ontology import draw_custom_nodes +logger = logging.getLogger(__name__) def expand_to_4d(array): @@ -845,7 +847,7 @@ def apply(self, timeseries, mode=0): if "Input" in self.graph.predecessors(node_label): node.update({"data": self.current_data}) elif node["data"] is None: - print("Node", node_label, "has no data") + logger.warning("Node %s has no data", node_label) continue time = ( diff --git a/tvbo/classes/perturbation.py b/tvbo/classes/perturbation.py index 0c28f32a..ea2d25fe 100644 --- a/tvbo/classes/perturbation.py +++ b/tvbo/classes/perturbation.py @@ -6,6 +6,7 @@ convert ontology classes to metadata and to replay audio files as stimuli. """ +import logging import os import matplotlib.pyplot as plt @@ -15,6 +16,7 @@ import librosa except ImportError: librosa = None +logger = logging.getLogger(__name__) def _require_librosa(): @@ -210,7 +212,7 @@ class directly. if not ontoclasses: raise ValueError(f"No stimulus class found for label '{ontoclass}'") if len(ontoclasses) > 1: - print(f"Multiple stimulus classes found: {ontoclasses}") + logger.warning("Multiple stimulus classes found: %s", ontoclasses) ontoclass = ontoclasses[0] metadata = class2metadata(ontoclass) return cls(**metadata._as_dict) @@ -313,7 +315,7 @@ def execute( ) if self.weighting: weighting = np.array(self.weighting) - print(weighting) + logger.debug("stimulus weighting: %s", weighting) elif weighting is None and connectivity: weighting = np.zeros(connectivity.number_of_regions) weighting[region_indices] = 1 diff --git a/tvbo/cli/__init__.py b/tvbo/cli/__init__.py index 94f567a1..d8ef12d1 100644 --- a/tvbo/cli/__init__.py +++ b/tvbo/cli/__init__.py @@ -70,4 +70,36 @@ app.add_typer(_skills_cmd.app, name="skills", help="Render skills for Claude Code / Copilot / Cursor; install user skills locally.") +@app.callback() +def _configure( + log_level: str = typer.Option( + None, "--log-level", "-L", metavar="LEVEL", + help="tvbo log level (DEBUG|INFO|WARNING|ERROR|OFF); overrides TVBO_LOG_LEVEL.", + ), + verbose: bool = typer.Option(False, "--verbose", "-v", help="Verbose output (DEBUG)."), + quiet: bool = typer.Option(False, "--quiet", "-q", help="Errors only — suppress progress."), +) -> None: + """Configure tvbo logging once for every verb. + + Progress and status flow through the central ``tvbo`` logger (see + :mod:`tvbo.log`), so ``tvbo run`` and the in-process ``.run()`` API behave + identically. ``--log-level`` wins over ``--quiet``/``--verbose``; with none + set the level falls back to ``TVBO_LOG_LEVEL`` and then INFO. + """ + from tvbo.log import configure_logging + + level = None + if verbose: + level = "DEBUG" + if quiet: + level = "ERROR" + if log_level: + level = log_level + # CLI output is user-facing: keep it bare (no "LEVEL [name]" diagnostic + # prefix), matching the plain lines the CLI printed before. force=True so + # this format wins even if ``import tvbo`` already installed the default + # (diagnostic) handler because ``TVBO_LOG_LEVEL`` was set in the environment. + configure_logging(level, fmt="%(message)s", force=True) + + __all__ = ["app"] diff --git a/tvbo/cli/_common.py b/tvbo/cli/_common.py index 2d3d5cff..4babdde7 100644 --- a/tvbo/cli/_common.py +++ b/tvbo/cli/_common.py @@ -5,12 +5,15 @@ from __future__ import annotations import json as _json +import logging import sys from pathlib import Path from typing import Any import typer +logger = logging.getLogger("tvbo.cli") + # --------------------------------------------------------------------------- # SPEC resolution @@ -181,10 +184,23 @@ def emit_json(payload: Any) -> None: def info(msg: str) -> None: - """Human-facing log line — always to stderr.""" - typer.echo(msg, err=True) + """Human-facing progress line, routed through the central ``tvbo`` logger. + + Emits at INFO on ``tvbo.cli`` (stderr by default), so ``--quiet`` / + ``TVBO_LOG_LEVEL`` govern it exactly as they govern in-process ``.run()``. + """ + logger.info(msg) def die(msg: str, code: int = 1) -> None: - typer.echo(f"error: {msg}", err=True) + """Log *msg* at ERROR and abort the CLI with *code*. + + A fatal abort must always explain itself: when the configured level would + suppress ERROR (e.g. ``--log-level OFF`` / ``TVBO_LOG_LEVEL=OFF``) the reason + still goes to stderr, so the CLI never exits non-zero in silence. + """ + if logger.isEnabledFor(logging.ERROR): + logger.error(msg) + else: + typer.echo(f"error: {msg}", err=True) raise typer.Exit(code) diff --git a/tvbo/codegen/code.py b/tvbo/codegen/code.py index 63e295e0..ebb54772 100644 --- a/tvbo/codegen/code.py +++ b/tvbo/codegen/code.py @@ -9,6 +9,8 @@ expression and prints it for the chosen backend. """ +import logging + import sympy.printing.julia as spj import sympy.printing.numpy as spn import sympy.printing.fortran as spf @@ -19,6 +21,8 @@ from tvbo.datamodel.schema import Equation from tvbo.parse.expression import parse_eq +logger = logging.getLogger(__name__) + # ============================================================================= # Array Function Printer Mappings @@ -193,15 +197,12 @@ def print_Piecewise(Printer, expr, verbose=False): result = default # Default fallback for np.where if verbose: - print("expr:", expr) - print("args:", args) - print("default:", default) + logger.debug("Piecewise expr=%s args=%s default=%s", expr, args, default) # Iterate over conditions and expressions in reverse order (excluding the default) for value, condition in reversed(args[:-1]): if verbose: - print("condition:", condition) - print("value:", value) + logger.debug("Piecewise branch: condition=%s value=%s", condition, value) condition_str = Printer._print(condition) value_str = Printer._print(value) # Build the nested conditional via the printer's backend-abstracted primitive @@ -209,8 +210,7 @@ def print_Piecewise(Printer, expr, verbose=False): result = Printer._where3(condition_str, value_str, result) if verbose: - print("result:", result) - print() + logger.debug("Piecewise result=%s", result) return result diff --git a/tvbo/codegen/templater.py b/tvbo/codegen/templater.py index 86cf868b..d5bb2637 100644 --- a/tvbo/codegen/templater.py +++ b/tvbo/codegen/templater.py @@ -11,6 +11,7 @@ coupling and integrator metadata from the ontology and render it into executable TVBO/TVB source using the templates in `tvbo.templates`. """ +import logging import re from os.path import join from typing import Any @@ -25,6 +26,18 @@ from tvbo.ontology import owl as ontology from tvbo.classes import equation as equations, coupling +logger = logging.getLogger(__name__) + + +def _log_source(rendered_code: str) -> None: + """Emit rendered code with line numbers when ``print_source`` is requested.""" + if not logger.isEnabledFor(logging.INFO): + return + numbered = "\n".join( + f"{i}\t{line}" for i, line in enumerate(rendered_code.split("\n"), start=1) + ) + logger.info("rendered source:\n%s", numbered) + exec_globals = {} TEMPLATES = templates.root @@ -289,9 +302,7 @@ def equation2class(EQ, fout=None, print_source=False, **kwargs): eq_type=eq_type, ) if print_source: - # Print each line with its line number - for i, line in enumerate(rendered_code.split("\n"), start=1): - print(f"{i}\t{line}") + _log_source(rendered_code) if fout: with open(fout, "w") as f: f.write(rendered_code) @@ -345,9 +356,7 @@ def coupling2class(CF, fout=None, print_source=False, **kwargs): sparse=sparse, ) if print_source: - # Print each line with its line number - for i, line in enumerate(rendered_code.split("\n"), start=1): - print(f"{i}\t{line}") + _log_source(rendered_code) if fout: with open(fout, "w") as f: f.write(rendered_code) @@ -475,9 +484,7 @@ def model2class( import_statements=import_statements, ) if print_source: - # Print each line with its line number - for i, line in enumerate(rendered_code.split("\n"), start=1): - print(f"{i}\t{line}") + _log_source(rendered_code) if fout: with open(fout, "w") as f: f.write(rendered_code) diff --git a/tvbo/data/types.py b/tvbo/data/types.py index f3835d98..beff98d4 100644 --- a/tvbo/data/types.py +++ b/tvbo/data/types.py @@ -6,6 +6,7 @@ stimulus, and monitor settings) handed to the integration backends. """ +import logging from copy import deepcopy import matplotlib.pyplot as plt @@ -25,6 +26,8 @@ from jax.tree_util import register_pytree_node_class import jax.numpy as jnp +logger = logging.getLogger(__name__) + def _to_dataarray(raw_data, raw_time=None, state_names=None, nodes=None): """Convert raw ndarray + metadata to xr.DataArray. @@ -2841,7 +2844,7 @@ def plot(self, ax=None, axis_labels=False, legend=True, title=None, **kwargs): n_svar = self.data.shape[1] if len(self.data.shape) > 1 else 1 uses_modes = len(self.data.shape) > 3 and self.data.shape[3] > 1 if uses_modes: - print("Plotting only first mode by default") + logger.info("Plotting only first mode by default") # n_regions = self.data.shape[2] if "labels" in kwargs.keys(): @@ -3299,7 +3302,7 @@ def compute_dt(self): dt = np.diff(self.time) mean_dt = np.mean(dt) if self.sample_period != mean_dt: - print("Warning: Sample period does not match mean dt. Setting sample period to mean dt.") + logger.warning("Sample period does not match mean dt; setting sample period to mean dt.") self.sample_period = mean_dt def plot_power_spectrum( diff --git a/tvbo/log.py b/tvbo/log.py new file mode 100644 index 00000000..d8d0d109 --- /dev/null +++ b/tvbo/log.py @@ -0,0 +1,252 @@ +# Copyright Berlin Institute of Health / Charité University Medicine Berlin +# Department of Neurology and Experimental Neurology +# Brain Simulation Section + +"""Central logging configuration for TVBO. + +Every part of TVBO logs through the ``tvbo`` logger hierarchy: + +* in-package modules use ``logger = logging.getLogger(__name__)`` — their names + already sit under ``tvbo`` (e.g. ``tvbo.classes.experiment``); +* generated backend scripts (tvboptim, …) use ``logging.getLogger("tvbo.run")`` + so their progress output is controlled by the very same switch, regardless of + which backend produced them or whether they run in-process or standalone. + +Importing tvbo as a library stays silent: the package installs only a +:class:`~logging.NullHandler`. Entry points that are meant to surface progress — +``tvbo run`` and :meth:`SimulationExperiment.run` — call :func:`configure_logging` +(directly, or via :func:`ensure_configured`) to attach a stderr handler. + +One switch controls all of it, no matter the entry point: + +* the ``TVBO_LOG_LEVEL`` environment variable + (``DEBUG`` / ``INFO`` / ``WARNING`` / ``ERROR`` / ``CRITICAL`` / ``OFF``), or +* :func:`set_log_level` / :func:`silence` at runtime, or +* an explicit ``configure_logging(level=...)``. + +Example: + >>> import tvbo + >>> tvbo.set_log_level("WARNING") # quiet the progress banners everywhere + >>> tvbo.silence() # turn tvbo logging off entirely +""" +from __future__ import annotations + +import logging +import os +from contextlib import contextmanager +from typing import Iterator, Optional, Union + +__all__ = [ + "logger", + "configure_logging", + "ensure_configured", + "set_log_level", + "get_log_level", + "silence", + "log_level", + "LOGGER_NAME", + "ENV_VAR", +] + +#: Root of the tvbo logger hierarchy; every package and generated-code logger is +#: a child of this and inherits its level and handlers. +LOGGER_NAME = "tvbo" +#: Environment variable read as the central level switch when nothing is passed. +ENV_VAR = "TVBO_LOG_LEVEL" +#: Level used when neither an explicit argument nor the env var is set. +DEFAULT_LEVEL = logging.INFO +#: Default stderr handler format for tvbo-managed output. +DEFAULT_FORMAT = "%(levelname)s [%(name)s] %(message)s" + +# Effective "off": above CRITICAL, so no standard record is ever emitted. +_OFF = logging.CRITICAL + 1 +# Marks the single handler this module owns, so configuration stays idempotent. +_MANAGED = "_tvbo_managed_handler" + +LevelLike = Union[int, str, None] + +logger = logging.getLogger(LOGGER_NAME) +# Library default: silent unless an entry point or the embedding app configures a +# handler. This replaces the old package-wide ``logging.disable(CRITICAL)``, +# which muted every logger in the process (tvbo's own included). +logger.addHandler(logging.NullHandler()) + + +def _coerce_level(level: LevelLike) -> Optional[int]: + """Turn a user-supplied level into a numeric level (``None`` passes through). + + Accepts ints, standard level names, and the aliases ``OFF``/``NONE``/ + ``SILENT``/``QUIET`` for "no output". + """ + if level is None: + return None + if isinstance(level, bool): # bool is an int subclass — treat explicitly + return logging.DEBUG if level else _OFF + if isinstance(level, int): + return level + text = str(level).strip().upper() + if text in ("OFF", "NONE"): + return _OFF + value = logging.getLevelName(text) # name → int for known levels + if isinstance(value, int): + return value + raise ValueError( + f"Unknown log level {level!r}; use an int or one of " + "DEBUG, INFO, WARNING, ERROR, CRITICAL, OFF." + ) + + +def _env_level() -> Optional[int]: + """Numeric level from ``TVBO_LOG_LEVEL``, or ``None`` if unset/invalid.""" + raw = os.environ.get(ENV_VAR) + if not raw or not raw.strip(): + return None + try: + return _coerce_level(raw) + except ValueError: + logging.getLogger(__name__).warning( + "Ignoring invalid %s=%r; expected DEBUG/INFO/WARNING/ERROR/CRITICAL/OFF.", + ENV_VAR, + raw, + ) + return None + + +def _resolve_level(level: LevelLike) -> int: + """Resolve a level with precedence: explicit arg → env var → default.""" + explicit = _coerce_level(level) + if explicit is not None: + return explicit + from_env = _env_level() + if from_env is not None: + return from_env + return DEFAULT_LEVEL + + +def _managed_handler(stream=None, fmt=None, datefmt=None) -> logging.Handler: + handler = logging.StreamHandler(stream) # stream=None → stderr + handler.setFormatter(logging.Formatter(fmt or DEFAULT_FORMAT, datefmt)) + setattr(handler, _MANAGED, True) + return handler + + +def _existing_managed() -> Optional[logging.Handler]: + return next((h for h in logger.handlers if getattr(h, _MANAGED, False)), None) + + +def _has_real_handler(target: logging.Logger) -> bool: + return any(not isinstance(h, logging.NullHandler) for h in target.handlers) + + +def _install_stream_handler(stream=None, fmt=None, datefmt=None, force=False) -> None: + """Install (idempotently) the single tvbo-managed stream handler. Level-agnostic.""" + existing = _existing_managed() + if existing is not None and not force: + return + if existing is not None: + logger.removeHandler(existing) + logger.addHandler(_managed_handler(stream, fmt, datefmt)) + # We own emission: don't also bubble to the root logger (avoids duplicate + # lines when the embedding application has configured root logging too). + logger.propagate = False + + +def configure_logging( + level: LevelLike = None, + *, + stream=None, + fmt: Optional[str] = None, + datefmt: Optional[str] = None, + force: bool = False, +) -> logging.Logger: + """Attach a stderr handler to the ``tvbo`` logger and set its level. + + Idempotent: the tvbo logger keeps at most one handler owned by this module. + When *level* is ``None`` the level falls back to ``TVBO_LOG_LEVEL`` and then + to :data:`DEFAULT_LEVEL`. Because the tvbo logger then owns its own output, + its records stop propagating to the root logger (so an embedding application + that also configured root logging does not print every line twice). + + Args: + level: Desired level (int, name, or ``"OFF"``); ``None`` → env → default. + stream: Target stream for the handler; ``None`` uses stderr. + fmt: Handler format string; ``None`` uses :data:`DEFAULT_FORMAT`. + datefmt: Optional date format for the handler. + force: Replace an existing tvbo-managed handler (e.g. to change stream). + + Returns: + The central ``tvbo`` logger. + """ + logger.setLevel(_resolve_level(level)) + _install_stream_handler(stream, fmt, datefmt, force=force) + return logger + + +def ensure_configured(level: LevelLike = None) -> logging.Logger: + """Make tvbo logs visible for a run without clobbering an app's logging setup. + + Called from the run entry points (``tvbo run``, ``SimulationExperiment.run``) + so that logging behaves the same however a run is launched: + + * if the tvbo logger or the root logger already has a real handler (an app, + notebook, or a prior :func:`configure_logging` set things up), only the + level is applied and the existing handlers keep emitting; + * otherwise a default stderr handler is installed via :func:`configure_logging`. + + A level explicitly set earlier (``set_log_level`` / ``silence`` / a prior + ``configure_logging``) is preserved: with no explicit *level* this only + installs a default level the first time (while the logger is still at + ``NOTSET``), so the central switch stays put across repeated ``.run()`` calls. + + Args: + level: Level to apply; ``None`` keeps any level already set, else falls + back to ``TVBO_LOG_LEVEL`` → :data:`DEFAULT_LEVEL` on first use. + + Returns: + The central ``tvbo`` logger. + """ + if level is not None: + logger.setLevel(_resolve_level(level)) + elif logger.level == logging.NOTSET: + logger.setLevel(_resolve_level(None)) + if _existing_managed() is not None: + return logger + if _has_real_handler(logger) or _has_real_handler(logging.getLogger()): + # Something already configured logging — let tvbo records flow to it. + return logger + _install_stream_handler() + return logger + + +def set_log_level(level: LevelLike) -> None: + """Set the central ``tvbo`` logger level — the global on/off/verbosity switch. + + Affects every tvbo module and every generated backend script in the process. + ``"OFF"`` (or :func:`silence`) turns tvbo logging off entirely. + """ + logger.setLevel(_resolve_level(level)) + + +def get_log_level() -> int: + """Return the effective numeric level of the central ``tvbo`` logger.""" + return logger.getEffectiveLevel() + + +def silence() -> None: + """Turn tvbo logging off (equivalent to ``TVBO_LOG_LEVEL=OFF``).""" + logger.setLevel(_OFF) + + +@contextmanager +def log_level(level: LevelLike) -> Iterator[logging.Logger]: + """Temporarily set the ``tvbo`` logger level within a ``with`` block. + + Useful to quiet a noisy section or to force verbosity in a test without + leaking the change to the rest of the process. + """ + previous = logger.level + logger.setLevel(_resolve_level(level)) + try: + yield logger + finally: + logger.setLevel(previous) diff --git a/tvbo/templates/autodiff/tvbo-jax-sim.py.mako b/tvbo/templates/autodiff/tvbo-jax-sim.py.mako index 218a4ecd..c45a6f48 100644 --- a/tvbo/templates/autodiff/tvbo-jax-sim.py.mako +++ b/tvbo/templates/autodiff/tvbo-jax-sim.py.mako @@ -88,12 +88,16 @@ ## print('simulation delayed:', is_delayed) %> +import logging + import jax from tvbo.data.types import TimeSeries from tvbo.utils import Bunch ## Usefull shorthands import jax.numpy as jnp +logger = logging.getLogger("tvbo.run") + <%include file="/tvbo-jax-coupling.py.mako" /> <%include file="/tvbo-jax-dfuns.py.mako" /> <%include file="/tvbo-jax-integrate.py.mako" /> @@ -386,6 +390,10 @@ def run_experiment(state): if __name__ == "__main__": import argparse from pathlib import Path as _Path + from tvbo.log import configure_logging + + # Standalone run: progress on stderr, controlled by TVBO_LOG_LEVEL (default INFO). + configure_logging() _parser = argparse.ArgumentParser(description="Run JAX-generated TVBO simulation") _parser.add_argument("--spec", type=_Path, default=None, @@ -405,7 +413,7 @@ if __name__ == "__main__": _experiment = SimulationExperiment.from_yaml(str(_spec)) _state = _experiment.collect_state() _result = kernel(_state) - print(f"Done: {type(_result).__name__}, shape={getattr(_result, 'shape', None)}") + logger.info("Done: %s, shape=%s", type(_result).__name__, getattr(_result, "shape", None)) if _args.output is not None: _args.output.mkdir(parents=True, exist_ok=True) @@ -414,4 +422,4 @@ if __name__ == "__main__": else: import numpy as _np _np.savez(_args.output / "result.npz", data=getattr(_result, "data", _result)) - print(f"Wrote results to {_args.output}") + logger.info("Wrote results to %s", _args.output) diff --git a/tvbo/templates/tvboptim/callbacks.py b/tvbo/templates/tvboptim/callbacks.py new file mode 100644 index 00000000..16065e45 --- /dev/null +++ b/tvbo/templates/tvboptim/callbacks.py @@ -0,0 +1,43 @@ +# Copyright Berlin Institute of Health / Charité University Medicine Berlin +# Department of Neurology and Experimental Neurology +# Brain Simulation Section + +"""Runtime callbacks for generated tvboptim scripts. + +Imported by the generated experiment/optimization scripts (which always run with +tvboptim available), so this module may depend on tvboptim. It routes optimizer +progress through the central ``tvbo.run`` logger (see :mod:`tvbo.log`), so one +switch — ``TVBO_LOG_LEVEL`` / ``tvbo.set_log_level`` / the CLI ``--quiet`` — +governs it exactly as it governs the rest of a run. +""" +from __future__ import annotations + +import logging +from typing import Optional + +from tvboptim.optim.callbacks import AbstractCallback + +logger = logging.getLogger("tvbo.run") + + +class LoggingProgressCallback(AbstractCallback): + """Log optimization progress at INFO every ``every`` steps. + + A logging-native, drop-in replacement for tvboptim's print-based + :class:`~tvboptim.optim.callbacks.DefaultPrintCallback`. When *total* is + given the line reads ``step i/total``. Never signals a stop. + + Args: + every: Emit one line every ``every`` steps (tvboptim gates the call). + total: Total step count, shown as ``i/total`` when known. + """ + + def __init__(self, every: int = 1, total: Optional[int] = None) -> None: + super().__init__(every) + self.total = total + + def do(self, i, diff_state, static_state, fitting_data, aux_data, loss_value, grads): + if logger.isEnabledFor(logging.INFO): + where = f"{i}/{self.total}" if self.total else str(i) + logger.info(" step %s: loss=%.6g", where, float(loss_value)) + return False, diff_state, static_state diff --git a/tvbo/templates/tvboptim/tvbo-tvboptim-algorithm.py.mako b/tvbo/templates/tvboptim/tvbo-tvboptim-algorithm.py.mako index 9ac700e7..ac437ea2 100644 --- a/tvbo/templates/tvboptim/tvbo-tvboptim-algorithm.py.mako +++ b/tvbo/templates/tvboptim/tvbo-tvboptim-algorithm.py.mako @@ -480,7 +480,7 @@ def run_${algo_name}( _${src_obs}_buffer = _passed_buffer[-int(window_size):].reshape((int(window_size), 1, n_nodes)) _buffer_idx = int(window_size) if verbose: - print(f" Using passed ${src_obs} buffer ({_passed_len} samples, using last {int(window_size)})") + logger.info(f" Using passed ${src_obs} buffer ({_passed_len} samples, using last {int(window_size)})") else: _${src_obs}_buffer = jnp.zeros((int(window_size), 1, n_nodes)) if _passed_buffer.ndim == 2: @@ -493,7 +493,7 @@ def run_${algo_name}( _${src_obs}_buffer = _${src_obs}_buffer.at[int(window_size) - _passed_len + _pi, 0, :].set(_passed_buffer[_pi]) _buffer_idx = _passed_len if verbose: - print(f" Passed ${src_obs} buffer too small ({_passed_len} < {int(window_size)}), running warmup for remaining {int(window_size) - _passed_len} samples...") + logger.info(f" Passed ${src_obs} buffer too small ({_passed_len} < {int(window_size)}), running warmup for remaining {int(window_size) - _passed_len} samples...") for _warmup_i in range(int(window_size) - _passed_len): key, subkey = jax.random.split(key) _warmup_result = model_fn(state) @@ -523,14 +523,14 @@ def run_${algo_name}( _${src_obs}_monitor = eqx.tree_at(history_accessor, _${src_obs}_monitor, _new_history) _buffer_idx = int(window_size) if verbose: - print(f" Warmup complete. Buffer filled with {_buffer_idx} samples.") + logger.info(f" Warmup complete. Buffer filled with {_buffer_idx} samples.") else: # No buffer passed - run warmup phase _${src_obs}_buffer = jnp.zeros((int(window_size), 1, n_nodes)) _buffer_idx = 0 if verbose: - print(f" Warmup: filling ${src_obs} buffer with {int(window_size)} samples...") + logger.info(f" Warmup: filling ${src_obs} buffer with {int(window_size)} samples...") for _warmup_i in range(int(window_size)): key, subkey = jax.random.split(key) @@ -562,7 +562,7 @@ def run_${algo_name}( _buffer_idx = int(window_size) if verbose: - print(f" Warmup complete. Buffer filled with {_buffer_idx} samples.") + logger.info(f" Warmup complete. Buffer filled with {_buffer_idx} samples.") % endfor % endif @@ -578,7 +578,7 @@ def run_${algo_name}( % endfor if verbose: - print(f"Running ${algo_name} algorithm for {n_iterations} iterations...") + logger.info(f"Running ${algo_name} algorithm for {n_iterations} iterations...") for i in range(n_iterations): key, subkey = jax.random.split(key) @@ -901,7 +901,6 @@ def run_${algo_name}( % endif % endfor - if verbose and (i + 1) % print_every == 0: <% # Build progress output - show functions (if any) + all simulated observations progress_items = [] @@ -923,8 +922,12 @@ def run_${algo_name}( progress_str = ", ".join(progress_parts) %> % if progress_items: - print(f" {i+1}/{n_iterations}: ${progress_str}") + # Gate on isEnabledFor so the progress f-string is only built when shown. + if verbose and logger.isEnabledFor(logging.INFO) and (i + 1) % print_every == 0: + logger.info(f" {i+1}/{n_iterations}: ${progress_str}") % else: + # Configuration guard — must fire regardless of the log level. + if verbose and (i + 1) % print_every == 0: raise ValueError("Algorithm must have functions or simulated_observations for progress display") % endif @@ -983,7 +986,7 @@ def run_${algo_name}( % endfor if verbose: - print(f"${algo_name} complete!") + logger.info(f"${algo_name} complete!") # Build hyperparameters Bunch for AlgorithmResult _hyperparams = Bunch( diff --git a/tvbo/templates/tvboptim/tvbo-tvboptim-experiment.py.mako b/tvbo/templates/tvboptim/tvbo-tvboptim-experiment.py.mako index 14f74f77..e5bc1fe9 100644 --- a/tvbo/templates/tvboptim/tvbo-tvboptim-experiment.py.mako +++ b/tvbo/templates/tvboptim/tvbo-tvboptim-experiment.py.mako @@ -1124,6 +1124,12 @@ first_coupling_name = list(all_couplings.keys())[0] if all_couplings else 'None' import os import copy import functools # render_expression emits functools.reduce for Min/Max over lists +import logging + +# Progress is logged, not printed: this generated script shares the ``tvbo`` +# logger hierarchy, so ``TVBO_LOG_LEVEL`` / ``tvbo.set_log_level`` control it the +# same way in-process and standalone (see the ``__main__`` block below). +logger = logging.getLogger("tvbo.run") import jax % if enable_x64: @@ -1157,7 +1163,8 @@ from tvboptim.experimental.network_dynamics.noise import AdditiveNoise import optax from tvboptim.types import Parameter, BoundedParameter from tvboptim.optim.optax import OptaxOptimizer -from tvboptim.optim.callbacks import MultiCallback, DefaultPrintCallback, SavingLossCallback, SavingParametersCallback +from tvboptim.optim.callbacks import MultiCallback, SavingLossCallback, SavingParametersCallback +from tvbo.templates.tvboptim.callbacks import LoggingProgressCallback % endif % if has_explorations: from tvboptim.types import Space, GridAxis, DataAxis @@ -2118,6 +2125,7 @@ def run_stage_${stage_name}( loss_fn, optimizer="${stage_algorithm}", learning_rate=learning_rate, + max_steps=max_steps, **opt_kwargs ) fitted_params, fitting_data = opt.run(marked_state, max_steps=max_steps, mode="${opt_mode}") @@ -2166,10 +2174,10 @@ def create_optimizer( if save_every is None: save_every = _smart_interval(max_steps) - # Default callback: print + save loss + save state at smart intervals + # Default callback: log progress + save loss + save state at smart intervals if callback is None: callback = MultiCallback([ - DefaultPrintCallback(every=print_every), + LoggingProgressCallback(every=print_every, total=max_steps), SavingLossCallback(every=save_every), SavingParametersCallback(every=save_every), ]) @@ -2964,18 +2972,22 @@ def run_experiment( _SEED_PARAMS = seed_params weights = jnp.array(weights) - # quiet=True silences the structural progress prints (run(..., quiet=True)). + # Progress flows through the ``tvbo.run`` logger; ``quiet=True`` forces + # silence for this call regardless of the configured level (back-compat with + # ``run(..., quiet=True)``), otherwise ``TVBO_LOG_LEVEL`` / the tvbo logger + # level decides what is shown. _quiet = kwargs.pop("quiet", False) - _log = (lambda *a, **k: None) if _quiet else print + + def _log(msg): + if not _quiet: + logger.info(msg) % if network_observation_names: # Materialize network-observation constants (empirical targets) from the # supplied matrices, keyed by observation name (e.g. {'fc_target': FC}). _bind_network_observations(network_observations) % endif - _log("\n" + "=" * 60) _log("STEP 1: Running simulation...") - _log("=" * 60) % if has_delay: if delays is None: @@ -3120,9 +3132,7 @@ def run_experiment( % if has_explorations: if mode in ('exploration', 'all'): - _log("\n" + "=" * 60) _log("STEP 2: Running explorations...") - _log("=" * 60) exploration_result = Bunch() % for expl in explorations: @@ -3142,9 +3152,7 @@ def run_experiment( % if has_algorithms: if mode in ('algorithm', 'algorithms', 'all'): - print("\n" + "=" * 60) - print("STEP 3: Running algorithms...") - print("=" * 60) + _log("STEP 3: Running algorithms...") # Determine if running all algorithms or just one algorithm_name = kwargs.get('name', kwargs.get('algorithm_name', None)) run_all_algorithms = (mode in ('algorithms', 'all')) or (algorithm_name is None and mode == 'algorithm') @@ -3258,7 +3266,7 @@ def run_experiment( if run_all_algorithms: # All algorithms run in dependency order (topological sort) algorithms_to_run = [${', '.join(f"'{n}'" for n in sorted_algo_names)}] - print(f" Algorithms to run (dependency order): {algorithms_to_run}") + _log(f" Algorithms to run (dependency order): {algorithms_to_run}") else: algorithms_to_run = [algorithm_name] @@ -3271,7 +3279,7 @@ def run_experiment( _algo_seed = default_algo_seed algo_key = jax.random.key(_algo_seed) # Use newer key() API for consistency if algo_verbose: - print(f"\\n>>> Running algorithm: {algorithm_name} (seed={_algo_seed})") + _log(f"\\n>>> Running algorithm: {algorithm_name} (seed={_algo_seed})") algo_result = None % for algo in algorithms_list: @@ -3363,11 +3371,11 @@ def run_experiment( if _dep_name in algorithms_results and hasattr(algorithms_results[_dep_name], 'state'): _source_state = algorithms_results[_dep_name].state if algo_verbose: - print(f" (using state from dependency: {_dep_name})") + _log(f" (using state from dependency: {_dep_name})") else: _source_state = initial_state if algo_verbose: - print(f" (dependency {_dep_name} not yet run, using initial state)") + _log(f" (dependency {_dep_name} not yet run, using initial state)") % else: # No dependencies - use initial state _source_state = initial_state @@ -3453,7 +3461,7 @@ def run_experiment( _stage_conv = [] # per-stage convergence Bunch (working-point trajectory) for _si, _sd in enumerate(_stage_defs): if algo_verbose: - print(f" [{algorithm_name} stage {_si+1}/{len(_stage_defs)}] {_sd}") + _log(f" [{algorithm_name} stage {_si+1}/{len(_stage_defs)}] {_sd}") algo_result = run_${algo_name}( state=_stage_state, model_fn=algo_model_fn, @@ -3574,9 +3582,7 @@ def run_experiment( results[_alg_name] = _alg_result # Use last algorithm's result as the "main" result last_algo_name = algorithms_to_run[-1] - print("\n" + "=" * 60) - print(f" Algorithms complete. Results: {list(algorithms_results.keys())}") - print("=" * 60) + _log(f" Algorithms complete. Results: {list(algorithms_results.keys())}") else: # Running single: expose result at top level results['algorithms'] = {algorithm_name: algo_result} @@ -3586,9 +3592,7 @@ def run_experiment( % if has_optimization: if mode in ('optimization', 'all'): - print("\n" + "=" * 60) - print("STEP 4: Running optimization...") - print("=" * 60) + _log("STEP 4: Running optimization...") _missing_inputs = [] % for kwarg_name in sorted(runtime_kwargs_needed) if runtime_kwargs_needed else []: if '${kwarg_name}' not in kwargs: @@ -3599,7 +3603,7 @@ def run_experiment( raise ValueError(f"Optimization requires these inputs via kwargs: {_missing_inputs}") else: # mode='all' - skip optimization if missing inputs - print(f" Skipping optimization (missing: {_missing_inputs})") + _log(f" Skipping optimization (missing: {_missing_inputs})") else: # Stage results storage (use Bunch for dot-notation access) stage_results = Bunch() @@ -3613,7 +3617,7 @@ def run_experiment( % if opt_has_custom_integration: # Prepare fresh model_fn and state for optimization # Optimization has custom integration settings: ${opt_solver_class} dt=${opt_dt} t1=${opt_t1} - print(f" Preparing optimization model (t1=${opt_t1}ms, dt=${opt_dt}ms, solver=${opt_solver_class})") + _log(f" Preparing optimization model (t1=${opt_t1}ms, dt=${opt_dt}ms, solver=${opt_solver_class})") % if opt_depends_on: # Use existing network (with history updated from algorithms) opt_model_fn, opt_state = prepare(network, get_solver(), t1=${opt_t1}, dt=${opt_dt}) @@ -3708,7 +3712,7 @@ ${search.refine_body(refine_info)}\ for _rk in list(stage_results.keys()): if not str(_rk).startswith('_'): results[_rk] = stage_results[_rk] - print(f" Refinement complete: {list(stage_results.keys())}") + _log(f" Refinement complete: {list(stage_results.keys())}") % else: % if len(optimization_stages) > 1: # Multi-stage optimization with optional stage filtering @@ -3718,10 +3722,10 @@ ${search.refine_body(refine_info)}\ if stage not in all_stage_names: raise ValueError(f"Unknown stage '{stage}'. Available stages: {all_stage_names}") stages_to_run = [stage] - print(f" Running single stage: {stage}") + _log(f" Running single stage: {stage}") else: stages_to_run = all_stage_names - print(f" Multi-stage optimization: ${len(optimization_stages)} stages") + _log(f" Multi-stage optimization: ${len(optimization_stages)} stages") % for stage_idx, stage in enumerate(optimization_stages): <% @@ -3732,20 +3736,20 @@ stage_lr = stage['learning_rate'] %> # Stage ${stage_idx + 1}: ${stage_name} if '${stage_name}' in stages_to_run: - print(f"\n>>> Stage ${stage_idx + 1}/${len(optimization_stages)}: ${stage_name}") - print(f" Free parameters: ${', '.join(p['name'] for p in stage['free_parameters'])}") + _log(f"\n>>> Stage ${stage_idx + 1}/${len(optimization_stages)}: ${stage_name}") + _log(f" Free parameters: ${', '.join(p['name'] for p in stage['free_parameters'])}") % if stage_warmup_from: - print(f" Warmup from: ${stage_warmup_from}") + _log(f" Warmup from: ${stage_warmup_from}") # Use fitted_params from warmup_from stage (or from kwargs if running single stage) if '${stage_warmup_from}' in stage_results: current_state = stage_results['${stage_warmup_from}'].fitted_params elif 'warmup_state' in kwargs: # Allow passing in state from previous run current_state = kwargs['warmup_state'] - print(f" Using warmup_state from kwargs") + _log(f" Using warmup_state from kwargs") elif stage is not None: # Running single stage without warmup - use initial state with warning - print(f" WARNING: warmup_from='${stage_warmup_from}' not available, using initial state") + _log(f" WARNING: warmup_from='${stage_warmup_from}' not available, using initial state") else: raise ValueError(f"warmup_from stage '${stage_warmup_from}' not found in completed stages: {list(stage_results.keys())}") % endif @@ -3778,9 +3782,7 @@ stage_lr = stage['learning_rate'] % endfor if stage is None: - print("\n" + "=" * 60) - print(" Multi-stage optimization complete") - print("=" * 60) + _log(" Multi-stage optimization complete") # Final results: last stage's fitted_params + per-stage access via dot notation results['fitted_params'] = current_state @@ -3832,25 +3834,21 @@ stage_lr = stage['learning_rate'] # Store under results.optimizations.{name} for consistent structure results['optimizations'] = Bunch(**{_opt_name: _opt_result}) results[_opt_name] = _opt_result # Also at top level for convenience - print(" Optimization complete.") + _log(" Optimization complete.") % endif % endif % endif % if has_inference: if mode in ('inference', 'all'): - print("\n" + "=" * 60) - print("STEP 5: Running Bayesian inference (MCMC)...") - print("=" * 60) + _log("STEP 5: Running Bayesian inference (MCMC)...") % for _inf in inference_list: ${render_inference(_inf, coupling_keys, external_input_keys, set(derived_observation_names), set(network_observation_names))} % endfor - print(f" Inference complete. Posteriors: {list(results.get('inferences', Bunch()).keys())}") + _log(f" Inference complete. Posteriors: {list(results.get('inferences', Bunch()).keys())}") % endif - _log("\n" + "=" * 60) _log("Experiment complete.") - _log("=" * 60) return results @@ -3879,15 +3877,18 @@ if __name__ == "__main__": import pickle from pathlib import Path from tvbo.data.types import ExperimentResult + from tvbo.log import configure_logging - print("=" * 60) - print("${dynamics_class} Experiment - Standalone Execution") - print("=" * 60) + # Standalone run: surface progress on stderr, controlled by TVBO_LOG_LEVEL + # (default INFO) — the same switch as ``tvbo run`` and ``exp.run(...)``. + configure_logging() + + logger.info("${dynamics_class} Experiment - Standalone Execution") % if has_bids: # Load network from BIDS (BEP017) from tvbo import Network as TVBONetwork - print("Loading network from BIDS: ${bids_dir}") + logger.info("Loading network from BIDS: ${bids_dir}") _network = TVBONetwork.from_bids( "${bids_dir}", % if structural_measures: @@ -3904,12 +3905,14 @@ if __name__ == "__main__": region_labels = list(_network.labels.keys()) if _network.labels else None except (AttributeError, TypeError): region_labels = None - print(f" Loaded network with {weights.shape[0]} nodes") + logger.info(" Loaded network with %d nodes", weights.shape[0]) % else: # No BIDS directory configured - check if weights available if 'weights' not in dir() or weights is None: - print("ERROR: Network weights not defined.") - print("Either configure network.bids_dir in YAML or call run_experiment() with weights.") + logger.error( + "Network weights not defined. Either configure network.bids_dir in " + "YAML or call run_experiment() with weights." + ) import sys sys.exit(1) distances = distances if 'distances' in dir() else None @@ -3945,16 +3948,14 @@ if __name__ == "__main__": output_path = Path(__file__).parent / "${safe_name(experiment.label or 'experiment')}_results.pkl" with open(output_path, 'wb') as f: pickle.dump(results, f) - print(f"\nResults saved to: {output_path}") + logger.info("Results saved to: %s", output_path) # Export BIDS-compatible output bids_output = Path(__file__).parent / "derivatives" results.export(bids_output, description="${safe_name(experiment.label or 'tvbsim')}") - print(f"BIDS output: {bids_output}") + logger.info("BIDS output: %s", bids_output) - # Summary - print("\n" + "=" * 60) - print("Results Summary") - print("=" * 60) + # Summary — the results object itself is the script's stdout payload. + logger.info("Results summary:") print(results) diff --git a/tvbo/templates/tvboptim/tvbo-tvboptim-optim.py.mako b/tvbo/templates/tvboptim/tvbo-tvboptim-optim.py.mako index 203aa17f..2c71ecfc 100644 --- a/tvbo/templates/tvboptim/tvbo-tvboptim-optim.py.mako +++ b/tvbo/templates/tvboptim/tvbo-tvboptim-optim.py.mako @@ -91,7 +91,8 @@ import jax.numpy as jnp from tvboptim.types import Parameter from tvboptim.optim.optax import OptaxOptimizer -from tvboptim.optim.callbacks import MultiCallback, DefaultPrintCallback +from tvboptim.optim.callbacks import MultiCallback +from tvbo.templates.tvboptim.callbacks import LoggingProgressCallback def mark_parameters_optimizable(state, n_nodes: int = ${n_nodes}): @@ -174,7 +175,7 @@ def create_optimizer( "sgd": optax.sgd, } opt_fn = optimizers.get(optimizer.lower(), optax.adam) - callback = MultiCallback([DefaultPrintCallback(every=print_every)]) + callback = MultiCallback([LoggingProgressCallback(every=print_every)]) return OptaxOptimizer(loss_fn, opt_fn(learning_rate), callback=callback, has_aux=has_aux)