fmuobs: control package logger levels in default runs

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)
 

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.

tests/test_fmuobs.py

@@ -2,14 +2,15 @@
 other formats, and test the ERT hook"""
 
 import io
+import logging
 import subprocess
 from pathlib import Path
 
 import pandas as pd
 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,23 +384,30 @@ 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"
     monkeypatch.chdir(tmp_path)
 
     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