log_level=INFO filters DEBUG from captured Jubilant logs

[github-actions]

Claims

The ops docs' "Log to a file" section shows a sample pyproject.toml with this comment above log_level = "INFO":

# Retain INFO logs in the "Captured log call" section when run interactively.
# Otherwise, that section will have DEBUG logs (coming from log_file_level).
log_level = "INFO"

I read two claims in there:

• A: Setting log_level = "INFO" retains INFO logs in the "Captured log call" section (i.e. it filters out DEBUG).
• B: Without log_level = "INFO" (but with log_file_level = "DEBUG"), the captured section fills up with DEBUG logs that "come from" log_file_level.

Issue #57 asks whether this really makes a difference with the latest Jubilant.

What I believe and why

I believe both claims are true, and the mechanism is in pytest's logging plugin rather than Jubilant itself — but the latest Jubilant is what supplies the INFO and DEBUG logs that make the setting meaningful.

From reading _pytest/logging.py: the file handler is wrapped around the whole test run (pytest_runtestloop) via catching_logs(self.log_file_handler, level=self.log_file_level). That context manager lowers the root logger to log_file_level (DEBUG), so DEBUG records start propagating. The per-test capture handler (caplog) is wrapped separately with catching_logs(self.caplog_handler, level=self.log_level):

• With log_level = "INFO": the capture handler is set to INFO, so it stores INFO+ and drops DEBUG — even though the root logger is at DEBUG. That is claim A.
• Without log_level (it resolves to None): the capture handler is left at NOTSET (captures everything), and since the root logger was already lowered to DEBUG by the file handler, DEBUG records get captured. That is claim B — the DEBUG logs "come from" log_file_level because log_file_level is what lowered the root logger.

The Jubilant side: Jubilant 1.12.0 (the latest, "Improved Jubilant logging", PR #351) changed juju.wait() so that app/unit status changes are logged at INFO (_log_short_status_if_needed) and the verbose gron diff is logged at DEBUG (logger_wait.debug('wait: status changed: ...')). So on the first poll of juju.wait() there is always at least one INFO record and one DEBUG record on the jubilant.wait logger. That is exactly the INFO/DEBUG split that log_level = "INFO" acts on. I pinned jubilant==1.12.0 in both charms.

What the PR tests

I used differential testing across the two k- charms (kepler + kosmos), which are structurally identical. Both have log_file_level = "DEBUG" and jubilant==1.12.0. They differ only in log_level:

• kepler: log_level = "INFO" (matches the doc sample).
• kosmos: no log_level (so the capture handler stays at NOTSET and DEBUG leaks in).

Both get the identical integration test test_log_level_filters_debug_from_captured_logs, which runs juju.wait(jubilant.all_active), filters caplog.records to the jubilant.wait logger, and asserts:

1. at least one INFO record is captured (the status-change logs are retained), and
2. no DEBUG record is captured (the gron diff is filtered out).

The kosmos copy is marked @pytest.mark.xfail(strict=True). The test bodies are identical modulo that marker.

What the CI result means

• If kepler's test passes and kosmos's xfails as expected: the doc is validated. log_level = "INFO" does make a difference with the latest Jubilant — it keeps Jubilant's INFO status-change logs in the captured section and filters out the DEBUG gron-diff logs, and without it the DEBUG logs leak in via log_file_level.
• If kepler's test fails (e.g. DEBUG is captured despite log_level = "INFO", or no INFO is captured): the doc is refuted.
• If kosmos unexpectedly passes (strict xfail): that would mean the behavioural difference doesn't exist — also a refutation of the claim that the setting matters.