diff --git a/CHANGELOG.md b/CHANGELOG.md index 02cea1cb8..8a840fbba 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -52,9 +52,20 @@ If upgrading from v2.x, see the [v3.0.0 release notes](https://github.com/flixOp Until here --> -## [6.0.3] - Upcoming +## [6.1.0] - Upcoming -**Summary**: Bugfix release fixing `cluster_weight` loss during NetCDF roundtrip for manually constructed clustered FlowSystems. +**Summary**: Adds solver log capture through the Python logging system, exposes `progress` and `log_fn` parameters on solve/optimize, and fixes `cluster_weight` loss during NetCDF roundtrip. + +### ✨ Added + +- **Solver log capture**: New `CONFIG.Solving.capture_solver_log` option routes solver output (HiGHS, Gurobi, etc.) through the `flixopt.solver` Python logger at INFO level. This allows capturing solver output in any Python log handler (console, file, or both) and filtering it independently from flixopt application logs. Enabled automatically by `CONFIG.debug()`, `CONFIG.exploring()`, `CONFIG.production()`, and `CONFIG.notebook()` presets. ([#606](https://github.com/flixOpt/flixopt/pull/606)) +- **`progress` parameter**: `solve()`, `optimize()`, and `rolling_horizon()` now accept a `progress` parameter (default `True`) to control the tqdm progress bar independently of CONFIG settings. +- **`log_fn` parameter**: `solve()` now accepts a `log_fn` parameter to persist the solver log to a file. + +### ♻️ Changed + +- **Presets**: `CONFIG.debug()` and `CONFIG.exploring()` now set `log_to_console=False` (solver output is routed through the Python logger instead of native console output). +- **`CONFIG.Solving.log_to_console`** now exclusively controls the solver's native console output. It no longer affects the tqdm progress bar (use the `progress` parameter instead). ### 🐛 Fixed diff --git a/docs/user-guide/optimization/index.md b/docs/user-guide/optimization/index.md index 5c8b0e3f1..12571ad67 100644 --- a/docs/user-guide/optimization/index.md +++ b/docs/user-guide/optimization/index.md @@ -282,6 +282,56 @@ Common solver parameters: - `mip_gap` - Acceptable optimality gap (0.01 = 1%) - `log_to_console` - Show solver output +## Logging & Solver Output + +By default, solvers print directly to the console. You can route this output +through Python's logging system using `capture_solver_log`, which forwards each +line to the `flixopt.solver` logger at INFO level. + +### Quick Setup with Presets + +```python +from flixopt import CONFIG + +CONFIG.exploring() # Console logging + solver capture (recommended for interactive use) +CONFIG.debug() # Verbose DEBUG logging + solver capture +CONFIG.production('flixopt.log') # File logging + solver capture, no console +``` + +### Manual Configuration + +`capture_solver_log` and `log_to_console` are independent settings: + +```python +# Route solver output through logger to console +CONFIG.Solving.capture_solver_log = True +CONFIG.Solving.log_to_console = False +CONFIG.Logging.enable_console('INFO') + +# Route solver output through logger to file +CONFIG.Solving.capture_solver_log = True +CONFIG.Solving.log_to_console = False +CONFIG.Logging.enable_file('INFO', 'flixopt.log') + +# Native solver console only (no Python logger) +CONFIG.Solving.capture_solver_log = False +CONFIG.Solving.log_to_console = True +``` + +!!! warning "Avoiding double console output" + If `capture_solver_log` and `log_to_console` are both `True` **and** the + `flixopt` logger has a console handler, solver output appears twice. Set + `log_to_console = False` when capturing to a console logger. + +### Persistent Solver Log File + +Pass `log_fn` to `solve()` to keep the raw solver log on disk: + +```python +flow_system.build_model() +flow_system.solve(fx.solvers.HighsSolver(), log_fn='solver.log') +``` + ## Performance Tips ### Model Size Reduction diff --git a/flixopt/config.py b/flixopt/config.py index 32724b4ae..7c7d0acd5 100644 --- a/flixopt/config.py +++ b/flixopt/config.py @@ -173,6 +173,7 @@ def format(self, record): 'log_to_console': True, 'log_main_results': True, 'compute_infeasibilities': True, + 'capture_solver_log': False, } ), } @@ -529,13 +530,36 @@ class Solving: log_to_console: Whether solver should output to console. log_main_results: Whether to log main results after solving. compute_infeasibilities: Whether to compute infeasibility analysis when the model is infeasible. + capture_solver_log: Whether to route solver output through the + ``flixopt.solver`` Python logger. When enabled, each solver + log line is forwarded at INFO level to + ``logging.getLogger('flixopt.solver')``. This setting is + independent of ``log_to_console`` — both can be active at the + same time. + + .. note:: + If ``capture_solver_log`` is ``True`` **and** + ``log_to_console`` is ``True`` **and** the ``flixopt`` + logger has a console handler, solver output will appear + on the console twice (once natively, once via the logger). + To avoid this, set ``log_to_console = False`` when + capturing to a console logger. Examples: ```python - # Set tighter convergence and longer timeout - CONFIG.Solving.mip_gap = 0.001 - CONFIG.Solving.time_limit_seconds = 600 + # Capture solver output to file only (no double console logging) + CONFIG.Solving.capture_solver_log = True + CONFIG.Solving.log_to_console = False # avoid double console output + CONFIG.Logging.enable_file('INFO', 'flixopt.log') + + # Capture through logger to console (disable native solver console) + CONFIG.Solving.capture_solver_log = True CONFIG.Solving.log_to_console = False + CONFIG.Logging.enable_console('INFO') + + # Native solver console only (no Python logger capture) + CONFIG.Solving.capture_solver_log = False + CONFIG.Solving.log_to_console = True ``` """ @@ -544,6 +568,7 @@ class Solving: log_to_console: bool = _DEFAULTS['solving']['log_to_console'] log_main_results: bool = _DEFAULTS['solving']['log_main_results'] compute_infeasibilities: bool = _DEFAULTS['solving']['compute_infeasibilities'] + capture_solver_log: bool = _DEFAULTS['solving']['capture_solver_log'] class Plotting: """Plotting configuration. @@ -668,6 +693,7 @@ def to_dict(cls) -> dict: 'log_to_console': cls.Solving.log_to_console, 'log_main_results': cls.Solving.log_main_results, 'compute_infeasibilities': cls.Solving.compute_infeasibilities, + 'capture_solver_log': cls.Solving.capture_solver_log, }, 'plotting': { 'default_show': cls.Plotting.default_show, @@ -698,13 +724,15 @@ def silent(cls) -> type[CONFIG]: cls.Plotting.default_show = False cls.Solving.log_to_console = False cls.Solving.log_main_results = False + cls.Solving.capture_solver_log = False return cls @classmethod def debug(cls) -> type[CONFIG]: """Configure for debug mode with verbose output. - Enables console logging at DEBUG level and all solver output for troubleshooting. + Enables console logging at DEBUG level and routes solver output through + the ``flixopt.solver`` Python logger for full capture. Examples: ```python @@ -714,15 +742,17 @@ def debug(cls) -> type[CONFIG]: ``` """ cls.Logging.enable_console('DEBUG') - cls.Solving.log_to_console = True + cls.Solving.log_to_console = False cls.Solving.log_main_results = True + cls.Solving.capture_solver_log = True return cls @classmethod def exploring(cls) -> type[CONFIG]: """Configure for exploring flixopt. - Enables console logging at INFO level and all solver output. + Enables console logging at INFO level and routes solver output through + the ``flixopt.solver`` Python logger. Also enables browser plotting for plotly with showing plots per default. Examples: @@ -734,8 +764,9 @@ def exploring(cls) -> type[CONFIG]: ``` """ cls.Logging.enable_console('INFO') - cls.Solving.log_to_console = True + cls.Solving.log_to_console = False cls.Solving.log_main_results = True + cls.Solving.capture_solver_log = True cls.browser_plotting() return cls @@ -761,6 +792,7 @@ def production(cls, log_file: str | Path = 'flixopt.log') -> type[CONFIG]: cls.Plotting.default_show = False cls.Solving.log_to_console = False cls.Solving.log_main_results = False + cls.Solving.capture_solver_log = True return cls @classmethod @@ -865,6 +897,7 @@ def notebook(cls) -> type[CONFIG]: # Disable verbose solver output for cleaner notebook cells cls.Solving.log_to_console = False cls.Solving.log_main_results = False + cls.Solving.capture_solver_log = True return cls diff --git a/flixopt/flow_system.py b/flixopt/flow_system.py index c61a15b70..e838c5480 100644 --- a/flixopt/flow_system.py +++ b/flixopt/flow_system.py @@ -1412,7 +1412,7 @@ def build_model(self, normalize_weights: bool | None = None) -> FlowSystem: return self - def solve(self, solver: _Solver) -> FlowSystem: + def solve(self, solver: _Solver, log_fn: pathlib.Path | str | None = None, progress: bool = True) -> FlowSystem: """ Solve the optimization model and populate the solution. @@ -1423,6 +1423,11 @@ def solve(self, solver: _Solver) -> FlowSystem: Args: solver: The solver to use (e.g., HighsSolver, GurobiSolver). + log_fn: Path to write the solver log file. If *None* and + ``capture_solver_log`` is enabled, a temporary file is used + (deleted after streaming). If a path is provided, the solver + log is persisted there regardless of capture settings. + progress: Whether to show a tqdm progress bar during solving. Returns: Self, for method chaining. @@ -1439,11 +1444,22 @@ def solve(self, solver: _Solver) -> FlowSystem: if self.model is None: raise RuntimeError('Model has not been built. Call build_model() first.') - self.model.solve( - solver_name=solver.name, - progress=CONFIG.Solving.log_to_console, - **solver.options, - ) + log_path = pathlib.Path(log_fn) if log_fn is not None else None + if CONFIG.Solving.capture_solver_log: + with fx_io.stream_solver_log(log_fn=log_path) as captured_path: + self.model.solve( + log_fn=captured_path, + solver_name=solver.name, + progress=progress, + **solver.options, + ) + else: + self.model.solve( + **({'log_fn': log_path} if log_path is not None else {}), + solver_name=solver.name, + progress=progress, + **solver.options, + ) if self.model.termination_condition in ('infeasible', 'infeasible_or_unbounded'): if CONFIG.Solving.compute_infeasibilities: diff --git a/flixopt/io.py b/flixopt/io.py index fb20a4d5c..d17a9147a 100644 --- a/flixopt/io.py +++ b/flixopt/io.py @@ -7,6 +7,9 @@ import pathlib import re import sys +import tempfile +import threading +import time import warnings from collections import defaultdict from contextlib import contextmanager @@ -1507,6 +1510,95 @@ def suppress_output(): pass # FD already closed or invalid +@contextmanager +def stream_solver_log(log_fn: pathlib.Path | None = None): + """Stream solver log file contents to the ``flixopt.solver`` Python logger. + + Tails a solver log file in a background thread, forwarding each line to + ``logging.getLogger('flixopt.solver')`` at INFO level. + + Use together with ``solver.options_for_log_capture`` to disable the + solver's native console output and route everything through the Python + logger instead. + + Note: + Some solvers (e.g. Gurobi) may print a small amount of output (license + banner, LP reading) directly to stdout before their console-log option + takes effect. This is a solver/linopy limitation. + + Args: + log_fn: Path to the solver log file. If *None*, a temporary file is + created and deleted after the context exits. If a path is provided, + the file is kept (useful when the caller wants a persistent solver + log alongside the Python logger stream). + + Yields: + Path to the log file. Pass it as ``log_fn`` to + ``linopy.Model.solve``. + + Warning: + Not thread-safe. Use only with sequential execution. + """ + solver_logger = logging.getLogger('flixopt.solver') + + # Resolve log file path + cleanup = log_fn is None + if cleanup: + fd, tmp_path = tempfile.mkstemp(suffix='.log', prefix='flixopt_solver_') + os.close(fd) + log_path = pathlib.Path(tmp_path) + else: + log_path = pathlib.Path(log_fn) + log_path.parent.mkdir(parents=True, exist_ok=True) + # Truncate existing file so the tail thread only streams new output + if log_path.exists(): + log_path.write_text('') + + stop_event = threading.Event() + + def _tail() -> None: + """Read lines from the log file and forward to the solver logger.""" + # Wait for the file to appear (linopy creates it) + while not log_path.exists() and not stop_event.is_set(): + time.sleep(0.01) + + if not log_path.exists(): + return + + with open(log_path) as f: + while not stop_event.is_set(): + line = f.readline() + if line: + stripped = line.rstrip('\n\r') + if stripped: + solver_logger.info(stripped) + else: + time.sleep(0.05) + + # Drain remaining lines after solve completes + for line in f: + stripped = line.rstrip('\n\r') + if stripped: + solver_logger.info(stripped) + + thread = threading.Thread(target=_tail, daemon=True) + thread.start() + + try: + yield log_path + finally: + # Give the tail thread a moment to catch the last writes + time.sleep(0.1) + stop_event.set() + thread.join(timeout=5) + + if cleanup: + try: + log_path.unlink(missing_ok=True) + except OSError: + pass + + # ============================================================================ # FlowSystem Dataset I/O # ============================================================================ diff --git a/flixopt/optimization.py b/flixopt/optimization.py index 21a4ebd87..4f5da92fa 100644 --- a/flixopt/optimization.py +++ b/flixopt/optimization.py @@ -243,12 +243,22 @@ def solve( t_start = timeit.default_timer() - self.model.solve( - log_fn=pathlib.Path(log_file) if log_file is not None else self.folder / f'{self.name}.log', - solver_name=solver.name, - progress=CONFIG.Solving.log_to_console, - **solver.options, - ) + log_fn = pathlib.Path(log_file) if log_file is not None else self.folder / f'{self.name}.log' + if CONFIG.Solving.capture_solver_log: + with fx_io.stream_solver_log(log_fn=log_fn) as log_path: + self.model.solve( + log_fn=log_path, + solver_name=solver.name, + progress=False, + **solver.options, + ) + else: + self.model.solve( + log_fn=log_fn, + solver_name=solver.name, + progress=CONFIG.Solving.log_to_console, + **solver.options, + ) self.durations['solving'] = round(timeit.default_timer() - t_start, 2) logger.log(SUCCESS_LEVEL, f'Model solved with {solver.name} in {self.durations["solving"]:.2f} seconds.') logger.info(f'Model status after solve: {self.model.status}') diff --git a/flixopt/optimize_accessor.py b/flixopt/optimize_accessor.py index d223da6ad..c87f1e713 100644 --- a/flixopt/optimize_accessor.py +++ b/flixopt/optimize_accessor.py @@ -14,7 +14,6 @@ import xarray as xr from tqdm import tqdm -from .config import CONFIG from .io import suppress_output if TYPE_CHECKING: @@ -59,6 +58,7 @@ def __call__( self, solver: _Solver, before_solve: Callable[[FlowSystem], None] | None = None, + progress: bool = True, normalize_weights: bool | None = None, ) -> FlowSystem: """ @@ -73,6 +73,7 @@ def __call__( before_solve: Optional callback function that receives the FlowSystem after building the model and before solving. Use this to add custom constraints via `flow_system.model.add_constraints()`. + progress: Whether to show a tqdm progress bar during solving. normalize_weights: Deprecated. Scenario weights are now always normalized in FlowSystem. Returns: @@ -122,7 +123,7 @@ def __call__( self._fs.build_model() if before_solve is not None: before_solve(self._fs) - self._fs.solve(solver) + self._fs.solve(solver, progress=progress) return self._fs def rolling_horizon( @@ -132,6 +133,7 @@ def rolling_horizon( overlap: int = 0, nr_of_previous_values: int = 1, before_solve: Callable[[FlowSystem], None] | None = None, + progress: bool = True, ) -> list[FlowSystem]: """ Solve the optimization using a rolling horizon approach. @@ -159,6 +161,7 @@ def rolling_horizon( before_solve: Optional callback function that receives each segment's FlowSystem after building the model and before solving. Use this to add custom constraints to each segment. + progress: Whether to show a tqdm progress bar for segment solving. Returns: List of segment FlowSystems, each with their individual solution. @@ -233,51 +236,42 @@ def rolling_horizon( desc='Solving segments', unit='segment', file=sys.stdout, - disable=not CONFIG.Solving.log_to_console, + disable=not progress, ) try: for i, (start_idx, end_idx) in progress_bar: progress_bar.set_description(f'Segment {i + 1}/{n_segments} (timesteps {start_idx}-{end_idx})') - # Suppress output when progress bar is shown (including logger and solver) - if CONFIG.Solving.log_to_console: - # Temporarily raise logger level to suppress INFO messages + # Suppress per-segment output when progress bar is shown + if progress: original_level = logger.level logger.setLevel(logging.WARNING) try: with suppress_output(): - segment_fs = self._fs.transform.isel(time=slice(start_idx, end_idx)) - if i > 0 and nr_of_previous_values > 0: - self._transfer_state( - source_fs=segment_flow_systems[i - 1], - target_fs=segment_fs, - horizon=horizon, - nr_of_previous_values=nr_of_previous_values, - ) - segment_fs.build_model() - if i == 0: - self._check_no_investments(segment_fs) - if before_solve is not None: - before_solve(segment_fs) - segment_fs.solve(solver) + segment_fs = self._solve_segment( + solver, + start_idx, + end_idx, + i, + segment_flow_systems, + horizon, + nr_of_previous_values, + before_solve, + ) finally: logger.setLevel(original_level) else: - segment_fs = self._fs.transform.isel(time=slice(start_idx, end_idx)) - if i > 0 and nr_of_previous_values > 0: - self._transfer_state( - source_fs=segment_flow_systems[i - 1], - target_fs=segment_fs, - horizon=horizon, - nr_of_previous_values=nr_of_previous_values, - ) - segment_fs.build_model() - if i == 0: - self._check_no_investments(segment_fs) - if before_solve is not None: - before_solve(segment_fs) - segment_fs.solve(solver) + segment_fs = self._solve_segment( + solver, + start_idx, + end_idx, + i, + segment_flow_systems, + horizon, + nr_of_previous_values, + before_solve, + ) segment_flow_systems.append(segment_fs) @@ -292,6 +286,34 @@ def rolling_horizon( return segment_flow_systems + def _solve_segment( + self, + solver: _Solver, + start_idx: int, + end_idx: int, + i: int, + previous_segments: list[FlowSystem], + horizon: int, + nr_of_previous_values: int, + before_solve: Callable[[FlowSystem], None] | None, + ) -> FlowSystem: + """Build and solve a single rolling-horizon segment.""" + segment_fs = self._fs.transform.isel(time=slice(start_idx, end_idx)) + if i > 0 and nr_of_previous_values > 0: + self._transfer_state( + source_fs=previous_segments[i - 1], + target_fs=segment_fs, + horizon=horizon, + nr_of_previous_values=nr_of_previous_values, + ) + segment_fs.build_model() + if i == 0: + self._check_no_investments(segment_fs) + if before_solve is not None: + before_solve(segment_fs) + segment_fs.solve(solver, progress=False) + return segment_fs + def _calculate_segment_indices(self, total_timesteps: int, horizon: int, overlap: int) -> list[tuple[int, int]]: """Calculate start and end indices for each segment.""" segments = [] diff --git a/tests/deprecated/test_config.py b/tests/deprecated/test_config.py index 94d626af2..04ed04e25 100644 --- a/tests/deprecated/test_config.py +++ b/tests/deprecated/test_config.py @@ -163,7 +163,7 @@ def test_preset_exploring(self, capfd): CONFIG.exploring() logger.info('exploring') assert 'exploring' in capfd.readouterr().out - assert CONFIG.Solving.log_to_console is True + assert CONFIG.Solving.log_to_console is False def test_preset_debug(self, capfd): """Test debug preset.""" diff --git a/tests/utilities/test_config.py b/tests/utilities/test_config.py index 94d626af2..a55a38d2f 100644 --- a/tests/utilities/test_config.py +++ b/tests/utilities/test_config.py @@ -163,7 +163,8 @@ def test_preset_exploring(self, capfd): CONFIG.exploring() logger.info('exploring') assert 'exploring' in capfd.readouterr().out - assert CONFIG.Solving.log_to_console is True + assert CONFIG.Solving.log_to_console is False + assert CONFIG.Solving.capture_solver_log is True def test_preset_debug(self, capfd): """Test debug preset."""