Make the log level configurable and add timestamps to the log output

changelog.md

@@ -2,6 +2,7 @@
 
 ### [Latest]
 
+- Make the log level configurable via `UPP_LOG_LEVEL` or `--log-level`, add timestamps to all log messages and write warnings and errors to stderr [#163](https://github.com/umami-hep/umami-preprocessing/pull/163)
 - Add container image documentation and generic Slurm/HTCondor submission scripts with config-driven component enumeration [#160](https://github.com/umami-hep/umami-preprocessing/pull/160)
 ### [v0.3.2](https://github.com/umami-hep/umami-preprocessing/releases/tag/v0.3.2) (04.08.2026)
 

docs/run.md

@@ -15,6 +15,22 @@ For a comprehensive list of available flags, refer to `preprocess --help`.
 
 !!!info "If you are running on lxplus you may need to use `python3 upp/main.py` instead of `preprocess`"
 
+### Logging
+
+By default UPP logs at the `INFO` level. You can change this with the `UPP_LOG_LEVEL`
+environment variable or with the `--log-level` flag, which wins over the environment variable:
+
+```bash
+export UPP_LOG_LEVEL=DEBUG
+preprocess --config path/to/config.yaml --log-level WARNING
+```
+
+The available levels are `DEBUG`, `INFO`, `WARNING`, `ERROR` and `CRITICAL`.
+
+Every log message is prefixed with the date and time. Debug and info messages are written to
+stdout while warnings, errors and critical messages are written to stderr, so in a batch job
+the `.out` file holds the progress of the run and the `.err` file only the problems.
+
 ### Splits 
 
 The data is divided into three splits: training (`train`), validation (`val`), and testing (`test`).

tests/unit/test_logger.py

@@ -1,12 +1,86 @@
 from __future__ import annotations
 
 import logging
+import re
 
-from upp.utils.logger import setup_logger
+import pytest
 
+from upp.utils import logger as upp_logger
+from upp.utils.logger import LOG_LEVEL_ENV, banner, resolve_log_level, setup_logger
 
-def test_setup_logger(caplog):
-    caplog.set_level(logging.DEBUG)
+
+@pytest.fixture(autouse=True)
+def reset_logger(monkeypatch):
+    monkeypatch.delenv(LOG_LEVEL_ENV, raising=False)
+    monkeypatch.setattr(upp_logger, "_configured_level", None)
+
+
+def test_setup_logger(capsys):
     logger = setup_logger(level="DEBUG")
     logger.debug("Debug message")
-    assert "Debug message" in caplog.text
+    assert "Debug message" in capsys.readouterr().out
+
+
+def test_resolve_log_level_default():
+    assert resolve_log_level() == "INFO"
+
+
+def test_resolve_log_level_from_env(monkeypatch):
+    monkeypatch.setenv(LOG_LEVEL_ENV, "debug")
+    assert resolve_log_level() == "DEBUG"
+
+
+def test_resolve_log_level_argument_wins(monkeypatch):
+    monkeypatch.setenv(LOG_LEVEL_ENV, "DEBUG")
+    assert resolve_log_level("WARNING") == "WARNING"
+
+
+def test_resolve_log_level_invalid(monkeypatch):
+    monkeypatch.setenv(LOG_LEVEL_ENV, "LOUD")
+    with pytest.raises(ValueError, match="Invalid log level LOUD"):
+        resolve_log_level()
+
+
+def test_setup_logger_uses_env(monkeypatch):
+    monkeypatch.setenv(LOG_LEVEL_ENV, "DEBUG")
+    setup_logger()
+    assert logging.getLogger().level == logging.DEBUG
+
+
+def test_setup_logger_keeps_first_level(monkeypatch):
+    setup_logger(level="DEBUG")
+    monkeypatch.setenv(LOG_LEVEL_ENV, "ERROR")
+    setup_logger()
+    assert logging.getLogger().level == logging.DEBUG
+
+
+def test_records_are_split_between_stdout_and_stderr(capsys):
+    setup_logger(level="DEBUG")
+    logging.debug("a debug record")
+    logging.info("an info record")
+    logging.warning("a warning record")
+    logging.error("an error record")
+
+    captured = capsys.readouterr()
+    assert "a debug record" in captured.out
+    assert "an info record" in captured.out
+    assert "a warning record" not in captured.out
+    assert "a warning record" in captured.err
+    assert "an error record" in captured.err
+    assert "an info record" not in captured.err
+
+
+def test_records_have_a_timestamp(capsys):
+    setup_logger(level="INFO")
+    logging.info("a timestamped record")
+    captured = capsys.readouterr()
+    assert re.search(r"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}", captured.out)
+
+
+def test_banner_fits_the_console_width(capsys):
+    setup_logger(level="INFO")
+    logging.info(banner(" Title "))
+    captured = capsys.readouterr()
+    lines = [line for line in captured.out.splitlines() if line.strip()]
+    assert len(lines) == 1
+    assert " Title " in lines[0]

tests/unit/test_main.py

@@ -4,7 +4,8 @@
 
 from pytest import fixture
 
-from upp.main import parse_args
+import upp.main
+from upp.main import main, parse_args
 
 
 @fixture
@@ -41,6 +42,7 @@ def test_parse_args_with_config(config_file):
         rw_merge_idx=None,
         files=None,
         skip_sample_check=False,
+        log_level=None,
     )
 
     assert parsed_args == expected_args
@@ -67,6 +69,7 @@ def test_parse_args_flags_not_given(config_file):
         rw_merge_idx=None,
         files=None,
         skip_sample_check=False,
+        log_level=None,
     )
     assert parsed_args == expected_args
 
@@ -104,6 +107,7 @@ def test_parse_args_flags_negative(config_file):
         rw_merge_idx=None,
         files=None,
         skip_sample_check=False,
+        log_level=None,
     )
 
     assert parsed_args == expected_args
@@ -139,6 +143,7 @@ def test_parse_args_flags_positive(config_file):
         rw_merge_idx=None,
         files=None,
         skip_sample_check=False,
+        log_level=None,
     )
 
     assert parsed_args == expected_args
@@ -176,6 +181,7 @@ def test_parse_args_component(config_file):
         rw_merge_idx=None,
         files=None,
         skip_sample_check=False,
+        log_level=None,
     )
 
     assert parsed_args == expected_args
@@ -213,6 +219,25 @@ def test_parse_args_region(config_file):
         rw_merge_idx=None,
         files=None,
         skip_sample_check=False,
+        log_level=None,
     )
 
     assert parsed_args == expected_args
+
+
+def test_main_runs_all_splits(config_file, monkeypatch):
+    splits = []
+    monkeypatch.setattr(upp.main, "run_pp", lambda args: splits.append(args.split))
+
+    main(["--config", str(config_file), "--split", "all"])
+
+    assert splits == ["train", "val", "test"]
+
+
+def test_main_runs_single_split(config_file, monkeypatch):
+    splits = []
+    monkeypatch.setattr(upp.main, "run_pp", lambda args: splits.append(args.split))
+
+    main(["--config", str(config_file), "--split", "val"])
+
+    assert splits == ["val"]

tests/unit/utils/test_check_input_samples.py

@@ -30,7 +30,7 @@ def info(self, *_a, **_k):
         def error(self, *_a, **_k):
             pass
 
-    monkeypatch.setattr(cis, "setup_logger", lambda: _Log())
+    monkeypatch.setattr(cis, "setup_logger", lambda *_: _Log())
 
     # H5Reader stub: we don't care about values here, just that it's called
     class _H5:
@@ -74,7 +74,7 @@ def error(self, *_a, **_k):
             self._errors += 1
 
     log = _Log()
-    monkeypatch.setattr(cis, "setup_logger", lambda: log)
+    monkeypatch.setattr(cis, "setup_logger", lambda *_: log)
 
     # H5Reader never called since pattern is invalid type
     class _H5:
@@ -100,7 +100,9 @@ def __init__(self, ntuple_dir: Path):
 
 def test_main_calls_pipeline_with_parsed_args(monkeypatch, tmp_path):
     # Build fake args returned by parse_args
-    ns = Namespace(config_path=tmp_path / "cfg.yaml", deviation_factor=3.0, verbose=True)
+    ns = Namespace(
+        config_path=tmp_path / "cfg.yaml", deviation_factor=3.0, verbose=True, log_level=None
+    )
     ns.config_path.write_text("")  # so valid path conversion is happy if reached
 
     # Monkeypatch parse_args to return our namespace regardless of input
@@ -155,7 +157,7 @@ def info(self, *_a, **_k):
         def error(self, *_a, **_k):
             pass
 
-    monkeypatch.setattr(cis, "setup_logger", lambda: _Log())
+    monkeypatch.setattr(cis, "setup_logger", lambda *_: _Log())
 
     # H5Reader stub
     class _H5:
@@ -201,7 +203,7 @@ def info(self, *_a, **_k):
         def error(self, *_a, **_k):
             pass
 
-    monkeypatch.setattr(cis, "setup_logger", lambda: _Log())
+    monkeypatch.setattr(cis, "setup_logger", lambda *_: _Log())
 
     class _H5:
         def __init__(self, **_kwargs):
@@ -276,7 +278,7 @@ def info(self, *_a, **_k):
         def error(self, *_a, **_k):
             pass
 
-    fake_logger.setup_logger = lambda: _Log()
+    fake_logger.setup_logger = lambda *_: _Log()
 
     # Inject fakes into sys.modules so the script can import them
     fakes = {

upp/main.py

@@ -30,7 +30,7 @@
 from upp.stages.rw_merge import RWMerge
 from upp.stages.split_containers import SplitContainers
 from upp.utils.check_input_samples import run_input_sample_check
-from upp.utils.logger import setup_logger
+from upp.utils.logger import banner, setup_logger
 
 
 def parse_args(args: Any) -> argparse.Namespace:
@@ -173,6 +173,13 @@ def parse_args(args: Any) -> argparse.Namespace:
         default=None,
         help="comma-separated list of files to use during the 'split-containers' stage ",
     )
+    parser.add_argument(
+        "--log-level",
+        default=None,
+        type=str.upper,
+        choices=["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"],
+        help="Logging level. Overrides the UPP_LOG_LEVEL environment variable.",
+    )
 
     args = parser.parse_args(args)
     d = vars(args)
@@ -188,6 +195,7 @@ def parse_args(args: Any) -> argparse.Namespace:
         "reweight",
         "rw_merge",
         "rw_merge_idx",
+        "log_level",
     ]
     if not any(v for a, v in d.items() if a not in ignore):
         for v in d:
@@ -204,7 +212,7 @@ def run_pp(args: argparse.Namespace) -> None:
     args : argparse.Namespace
         Parsed command line arguments
     """
-    log = setup_logger()
+    log = setup_logger(args.log_level)
 
     # print start info
     log.info("[bold green]Starting preprocessing...")
@@ -271,31 +279,28 @@ def run_pp(args: argparse.Namespace) -> None:
 
     # make plots
     if args.plot:
-        title = " Plotting "
-        log.info(f"[bold green]{title:-^100}")
+        log.info(banner(" Plotting "))
         plot_resampling_dists(config=config, stage="initial")
         plot_resampling_dists(config=config, stage=args.split)
 
     # print end info
     end = datetime.now()
-    title = " Finished Preprocessing! "
-    log.info(f"[bold green]{title:-^100}")
+    log.info(banner(" Finished Preprocessing! "))
     log.info(f"End time: {end.strftime('%Y-%m-%d %H:%M:%S')}")
     log.info(f"Elapsed time: {str(end - start).split('.')[0]}")
 
 
 def main(args: Any | None = None) -> None:
     args = parse_args(args)
-    log = setup_logger()
+    log = setup_logger(args.log_level)
 
     if args.split == "all":
         d = vars(args)
         for split in ["train", "val", "test"]:
             d["split"] = split
-            log.info(f"[bold blue]{'-' * 100}")
-            title = f" {args.split} "
-            log.info(f"[bold blue]{title:-^100}")
-            log.info(f"[bold blue]{'-' * 100}")
+            log.info(banner(style="bold blue"))
+            log.info(banner(f" {args.split} ", style="bold blue"))
+            log.info(banner(style="bold blue"))
             run_pp(args)
     else:
         run_pp(args)

upp/stages/hist.py

@@ -12,7 +12,7 @@
 from numpy.lib.recfunctions import structured_to_unstructured as s2u
 from scipy.stats import binned_statistic_dd
 
-from upp.utils.logger import setup_logger
+from upp.utils.logger import banner, setup_logger
 
 if TYPE_CHECKING:  # pragma: no cover
     from upp.classes.preprocessing_config import PreprocessingConfig
@@ -154,8 +154,7 @@ def create_histograms(
         return
     sampl_vars = config.sampl_cfg.vars
 
-    title = " Writing PDFs "
-    log.info(f"[bold green]{title:-^100}")
+    log.info(banner(" Writing PDFs "))
     log.info(
         f"[bold green]Estimating PDFs using {config.num_global_objects_estimate_hist:,} objects..."
     )

upp/stages/merging.py

@@ -10,7 +10,7 @@
 import numpy as np
 from ftag.hdf5 import H5Writer, join_structured_arrays
 
-from upp.utils.logger import ProgressBar
+from upp.utils.logger import ProgressBar, banner
 from upp.utils.tools import path_append
 
 if TYPE_CHECKING:  # pragma: no cover
@@ -611,8 +611,7 @@ def write_components(self, sample: str | None, components: Components) -> None:
 
     def run(self):
         """Run merging of the components."""
-        title = " Running Merging "
-        log.info(f"[bold green]{title:-^100}")
+        log.info(banner(" Running Merging "))
 
         if not self.config.is_test or self.config.merge_test_samples:
             components = [(None, self.components)]

upp/stages/normalisation.py

@@ -8,7 +8,7 @@
 import yaml
 from ftag.hdf5 import H5Reader
 
-from upp.utils.logger import ProgressBar
+from upp.utils.logger import ProgressBar, banner
 
 if TYPE_CHECKING:  # pragma: no cover
     from upp.classes.preprocessing_config import PreprocessingConfig
@@ -231,8 +231,7 @@ def write_class_dict(self, class_dict: dict) -> None:
 
     def run(self):
         """Run the normalisation calculation."""
-        title = " Computing Normalisations "
-        log.info(f"[bold green]{title:-^100}")
+        log.info(banner(" Computing Normalisations "))
         if self.config.rw_config is not None:
             fname = str(self.config.out_fname).replace(".h5", "_vds.h5")