From 0856399d5b9cad27c7b233a2ab46f2d41b06dbb5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Roger=20Nyb=C3=B8?= Date: Wed, 7 Oct 2026 15:58:12 +0200 Subject: [PATCH 1/2] fmuobs: control package logger levels in default runs - Add configure_logging to set levels for fmuobs and its submodules - Default to WARNING so INFO/DEBUG output no longer leaks in ERT hooks - Keep stdout guard when verbose/debug is used with stdout output - Extend workflow hook test to assert INFO/DEBUG output per mode --- src/subscript/fmuobs/fmuobs.py | 35 +++++++++++----- tests/test_fmuobs.py | 75 ++++++++++++++++++++++++---------- 2 files changed, 78 insertions(+), 32 deletions(-) diff --git a/src/subscript/fmuobs/fmuobs.py b/src/subscript/fmuobs/fmuobs.py index 6b8c4c084..ea5e9c1d0 100644 --- a/src/subscript/fmuobs/fmuobs.py +++ b/src/subscript/fmuobs/fmuobs.py @@ -293,6 +293,28 @@ def main() -> None: ) +def configure_logging(verbose: bool = False, debug: bool = False) -> None: + """Configure log levels for fmuobs and its submodules. + + The ERT workflow hook captures log output from the Python process, so we + must explicitly control the package logger levels here to avoid leaking + INFO/DEBUG output in default runs. + """ + loglevel = logging.WARNING + if verbose: + loglevel = logging.INFO + if debug: + loglevel = logging.DEBUG + + for name in ( + "subscript.fmuobs", + "subscript.fmuobs.parsers", + "subscript.fmuobs.writers", + "subscript.fmuobs.util", + ): + logging.getLogger(name).setLevel(loglevel) + + def fmuobs( inputfile: str, ertobs: str | None = None, @@ -305,16 +327,9 @@ def fmuobs( includedir: str | None = None, ) -> None: """Alternative to main() with named arguments""" - if verbose or debug: - if __MAGIC_STDOUT__ in {csv, yml, ertobs}: - raise SystemExit("Don't use verbose/debug when writing to stdout") - loglevel = logging.INFO - if debug: - loglevel = logging.DEBUG - logger.setLevel(loglevel) - getLogger("subscript.fmuobs.parsers").setLevel(loglevel) - getLogger("subscript.fmuobs.writers").setLevel(loglevel) - getLogger("subscript.fmuobs.util").setLevel(loglevel) + if (verbose or debug) and __MAGIC_STDOUT__ in {csv, yml, ertobs}: + raise SystemExit("Don't use verbose/debug when writing to stdout") + configure_logging(verbose=verbose, debug=debug) (filetype, dframe) = autoparse_file(inputfile) diff --git a/tests/test_fmuobs.py b/tests/test_fmuobs.py index 4fb9d26a1..0c9de6397 100644 --- a/tests/test_fmuobs.py +++ b/tests/test_fmuobs.py @@ -2,6 +2,7 @@ other formats, and test the ERT hook""" import io +import logging import subprocess from pathlib import Path @@ -9,7 +10,7 @@ import pytest import yaml -from subscript.fmuobs.fmuobs import autoparse_file, main +from subscript.fmuobs.fmuobs import autoparse_file, fmuobs, main from subscript.fmuobs.parsers import ertobs2df, obsdict2df, resinsight_df2df from subscript.fmuobs.writers import df2ertobs, df2obsdict, df2resinsight_df @@ -302,8 +303,7 @@ def test_commandline(tmp_path, verbose, mocker, caplog, monkeypatch): """Test the executable versus on the ERT doc observation data and compare to precomputed CSV and YML. - When code changes, updates to the CSV and YML might - be necessary. + When code changes, updates to the CSV and YML might be necessary. """ monkeypatch.chdir(tmp_path) mocker.patch( @@ -312,7 +312,6 @@ def test_commandline(tmp_path, verbose, mocker, caplog, monkeypatch): filter( None, [ - # [ "fmuobs", "--includedir", str(TESTDATA_DIR), @@ -385,8 +384,16 @@ def test_commandline(tmp_path, verbose, mocker, caplog, monkeypatch): ) +def _has_log(output: str, level: str, logger_name: str, text: str) -> bool: + """True if some ERT log line has this logger, level and message text""" + return any( + f" - {logger_name} - " in line and f" - {level} - " in line and text in line + for line in output.splitlines() + ) + + @pytest.mark.integration -@pytest.mark.parametrize("verbose", ["", '"--verbose"', '"--debug"']) +@pytest.mark.parametrize("verbose", ["", "--verbose", "--debug"]) def test_ert_workflow_hook(verbose, tmp_path, monkeypatch): """Mock an ERT config with FMUOBS as a workflow and run it""" obs_file = TESTDATA_DIR / "ert-doc.obs" @@ -394,14 +401,13 @@ def test_ert_workflow_hook(verbose, tmp_path, monkeypatch): Path("FOO.DATA").write_text("--Empty", encoding="utf8") + # ERT treats "--" as a comment, so options must be quoted in the workflow + quoted_verbose = f'"{verbose}"' if verbose else "" + Path("wf_fmuobs").write_text( - "FMUOBS " - + verbose - + " " - + str(obs_file) - + ' "--yaml" ert-obs.yml "--resinsight" ri-obs.csv "--includedir" ' - + str(TESTDATA_DIR) - + "\n", + f"FMUOBS {quoted_verbose} {obs_file} " + '"--yaml" ert-obs.yml "--resinsight" ri-obs.csv ' + f'"--includedir" {TESTDATA_DIR}\n', encoding="utf8", ) @@ -424,18 +430,43 @@ def test_ert_workflow_hook(verbose, tmp_path, monkeypatch): # Verify that we can control whether INFO messages from fmuobs through ERT # is emitted. - log_file = next(Path("logs").glob("ert-log*txt")) - ert_output = log_file.read_text(encoding="utf-8") + logs = list(Path("logs").glob("ert-log*txt")) + assert logs, "No ERT log file found" + ert_output = logs[0].read_text(encoding="utf-8") + + parsers = "subscript.fmuobs.parsers" + # Positive control: the log file must contain fmuobs messages at WARNING + # level, which are emitted in every mode. Otherwise the absence checks + # below could pass on an empty or wrong file. + assert _has_log(ert_output, "WARNING", "subscript.fmuobs.writers", "missing DATE") - # This is slightly tricky, as ERT has its own logging handler which is able - # to pick up the log messages, but whose level cannot be controlled by - # the fmuobs.py file. Thus, we test on the exact subscript logger format: if verbose == "--verbose": - assert "INFO:subscript.fmuobs.parsers:Injecting include file" in ert_output + assert _has_log(ert_output, "INFO", parsers, "Injecting include file") + assert not _has_log(ert_output, "DEBUG", parsers, "Parsing observation") elif verbose == "--debug": - assert ( - "DEBUG:subscript.fmuobs.parsers:" - "Parsing observation SUMMARY_OBSERVATION SEP_TEST_2005" in ert_output + assert _has_log(ert_output, "INFO", parsers, "Injecting include file") + assert _has_log( + ert_output, + "DEBUG", + parsers, + "Parsing observation SUMMARY_OBSERVATION SEP_TEST_2005", ) else: - assert "INFO:subscript.fmuobs.parsers:Injecting include file" not in ert_output + assert not _has_log(ert_output, "INFO", parsers, "Injecting include file") + assert not _has_log(ert_output, "DEBUG", parsers, "Parsing observation") + + +def test_stdout_guard_does_not_change_log_levels(tmp_path, monkeypatch): + """A rejected verbose+stdout call must not alter logger levels""" + monkeypatch.chdir(tmp_path) + logger = logging.getLogger("subscript.fmuobs") + logger.setLevel(logging.WARNING) + + with pytest.raises(SystemExit): + fmuobs( + str(TESTDATA_DIR / "ert-doc.obs"), + csv="-", + verbose=True, + ) + + assert logger.level == logging.WARNING From 75cda1f18254b83cb5d8dbb5709388878c64d563 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Roger=20Nyb=C3=B8?= Date: Thu, 8 Oct 2026 09:38:01 +0200 Subject: [PATCH 2/2] fix(fmuobs): use correct dataframe when filling default segment - Replace reference to history_obs_df with history_df in SEGMENT fillna --- src/subscript/fmuobs/writers.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/subscript/fmuobs/writers.py b/src/subscript/fmuobs/writers.py index 4aaae1f2c..ad76b39df 100644 --- a/src/subscript/fmuobs/writers.py +++ b/src/subscript/fmuobs/writers.py @@ -130,7 +130,7 @@ def dfhistory2ertobs(obs_df: pd.DataFrame) -> str: if "SEGMENT" not in history_df: history_df["SEGMENT"] = "DEFAULT" else: - history_df["SEGMENT"] = history_obs_df["SEGMENT"].fillna(value="DEFAULT") + history_df["SEGMENT"] = history_df["SEGMENT"].fillna(value="DEFAULT") ertobs_str += "HISTORY_OBSERVATION " + str(histlabel) + " \n" ertobs_str += "{\n" # Write statements for the implicit DEFAULT segment.