From 2cdaf3dafef32a42769c3d224c600c589aceaa5b Mon Sep 17 00:00:00 2001 From: Ramesh Padmanabhaiah <22363102+codeforester@users.noreply.github.com> Date: Wed, 30 Sep 2026 19:59:08 +0530 Subject: [PATCH 1/3] fix: namespace log timestamp configuration --- docs/integrations.md | 7 +++++++ lib/python/base_cli/logging.py | 19 ++++++++++++++++++- tests/test_logging.py | 19 +++++++++++++++++++ 3 files changed, 44 insertions(+), 1 deletion(-) diff --git a/docs/integrations.md b/docs/integrations.md index 0bfb68c..38e095c 100644 --- a/docs/integrations.md +++ b/docs/integrations.md @@ -52,3 +52,10 @@ outcome, exit code, and duration. Raw argv, configuration values, filesystem paths, and secrets are never attached. A missing API package, invalid provider, or failing exporter is logged at debug level and treated as a no-op; it cannot change the command's exit status or cleanup behavior. + +## Log timestamp environment variable + +Set `BASE_CLI_LOG_UTC=1` to make the default text formatter use UTC +timestamps. The namespaced variable takes precedence over the legacy setting. +`LOG_UTC` remains recognized during the 0.5 compatibility window, but emits a +`BaseCliDeprecationWarning` and is scheduled for removal in 0.6. diff --git a/lib/python/base_cli/logging.py b/lib/python/base_cli/logging.py index 35aa824..0ecea37 100644 --- a/lib/python/base_cli/logging.py +++ b/lib/python/base_cli/logging.py @@ -5,6 +5,7 @@ import platform import sys import time +import warnings from io import TextIOWrapper from pathlib import Path from typing import BinaryIO, TextIO, cast @@ -21,6 +22,7 @@ from ._private_files import restrict_file from .context import get_current_context +from .deprecations import BaseCliDeprecationWarning from .history import compact_home_text from .json_contracts import JsonLogFormatter from .paths import current_working_dir @@ -213,7 +215,22 @@ def _secure_log_file_open_flags(mode: str) -> int: class CliFormatter(logging.Formatter): def __init__(self, *, use_utc: bool | None = None, use_color: bool = False) -> None: - self.use_utc = use_utc if use_utc is not None else os.environ.get("LOG_UTC") == "1" + if use_utc is not None: + resolved_use_utc = use_utc + else: + configured_use_utc = os.environ.get("BASE_CLI_LOG_UTC") + legacy_use_utc = os.environ.get("LOG_UTC") + if configured_use_utc is not None: + resolved_use_utc = configured_use_utc == "1" + else: + if legacy_use_utc is not None: + warnings.warn( + "LOG_UTC is deprecated since 0.5 and will be removed in 0.6; use BASE_CLI_LOG_UTC instead.", + BaseCliDeprecationWarning, + stacklevel=2, + ) + resolved_use_utc = legacy_use_utc == "1" + self.use_utc = resolved_use_utc self.use_color = use_color datefmt = "%Y-%m-%d %H:%M:%S UTC" if self.use_utc else "%Y-%m-%d %H:%M:%S %z" super().__init__(datefmt=datefmt) diff --git a/tests/test_logging.py b/tests/test_logging.py index 6f85b75..3a85c01 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -6,6 +6,7 @@ import sys import tempfile import unittest +import warnings from pathlib import Path from unittest import mock @@ -122,6 +123,24 @@ def test_configure_logger_honors_log_utc(self) -> None: self.assertRegex(stream.getvalue(), r"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2} UTC INFO") + def test_configure_logger_honors_namespaced_log_utc_and_precedence(self) -> None: + stream = io.StringIO() + + with mock.patch.dict(os.environ, {"BASE_CLI_LOG_UTC": "1", "LOG_UTC": "0"}): + logger = base_cli.configure_logger("namespaced-utc-stream", None, debug=False, stream=stream) + logger.info("hello utc") + + self.assertRegex(stream.getvalue(), r"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2} UTC INFO") + + def test_legacy_log_utc_emits_deprecation_warning(self) -> None: + with mock.patch.dict(os.environ, {"LOG_UTC": "1"}, clear=True): + with warnings.catch_warnings(record=True) as caught: + warnings.simplefilter("always", base_cli.BaseCliDeprecationWarning) + CliFormatter() + + self.assertEqual(len(caught), 1) + self.assertIn("BASE_CLI_LOG_UTC", str(caught[0].message)) + def test_configure_logger_colors_python_user_stream_when_requested(self) -> None: stream = self._TtyStream() From d4c39ce3219ff23f7404cbcdf9f9924cb17d48d6 Mon Sep 17 00:00:00 2001 From: Ramesh Padmanabhaiah <22363102+codeforester@users.noreply.github.com> Date: Thu, 1 Oct 2026 00:19:50 +0530 Subject: [PATCH 2/3] docs: complete log timestamp migration --- CHANGELOG.md | 3 +++ README.md | 5 +++++ docs/integrations.md | 2 +- lib/python/base_cli/logging.py | 12 ++++++------ tests/test_logging.py | 22 ++++++++++++++++++++-- 5 files changed, 35 insertions(+), 9 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 59d0ef2..3f942ff 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -20,6 +20,9 @@ and versions are tracked in the repo-root `VERSION` file. - Align the Typer support floor with the tested matrix and cover representative minimum/maximum Typer and Click version pairings. +- Add the namespaced `BASE_CLI_LOG_UTC` environment variable and deprecate + `LOG_UTC` with a migration warning; the legacy alias is scheduled for removal + no earlier than 0.7. ### Fixed diff --git a/README.md b/README.md index cf7f8cf..20c13dd 100644 --- a/README.md +++ b/README.md @@ -568,6 +568,11 @@ Every `base_cli.App` command gets these options: - `--json`: opt-in machine output, when `LifecycleOptions.json` is enabled; emits the versioned envelopes described in [`docs/json-contracts.md`](https://basefoundry.github.io/base-cli/json-contracts/). +Set `BASE_CLI_LOG_UTC=1` when the default text formatter should use UTC +timestamps. The older `LOG_UTC` name remains a temporary compatibility alias +and emits a deprecation warning; new deployments should use the namespaced +variable. + `LifecycleOptions()` preserves this default set. Its `debug`, `quiet`, `environment`, `config`, `keep_temp`, `log_file`, and `version` fields are enabled by default; `dry_run` and `json` are opt-in. Set one field to `None` to diff --git a/docs/integrations.md b/docs/integrations.md index 38e095c..2c27178 100644 --- a/docs/integrations.md +++ b/docs/integrations.md @@ -58,4 +58,4 @@ change the command's exit status or cleanup behavior. Set `BASE_CLI_LOG_UTC=1` to make the default text formatter use UTC timestamps. The namespaced variable takes precedence over the legacy setting. `LOG_UTC` remains recognized during the 0.5 compatibility window, but emits a -`BaseCliDeprecationWarning` and is scheduled for removal in 0.6. +`BaseCliDeprecationWarning` and is scheduled for removal no earlier than 0.7. diff --git a/lib/python/base_cli/logging.py b/lib/python/base_cli/logging.py index 0ecea37..a733287 100644 --- a/lib/python/base_cli/logging.py +++ b/lib/python/base_cli/logging.py @@ -220,15 +220,15 @@ def __init__(self, *, use_utc: bool | None = None, use_color: bool = False) -> N else: configured_use_utc = os.environ.get("BASE_CLI_LOG_UTC") legacy_use_utc = os.environ.get("LOG_UTC") + if legacy_use_utc: + warnings.warn( + "LOG_UTC is deprecated since 0.5 and will be removed in 0.7; use BASE_CLI_LOG_UTC instead.", + BaseCliDeprecationWarning, + stacklevel=2, + ) if configured_use_utc is not None: resolved_use_utc = configured_use_utc == "1" else: - if legacy_use_utc is not None: - warnings.warn( - "LOG_UTC is deprecated since 0.5 and will be removed in 0.6; use BASE_CLI_LOG_UTC instead.", - BaseCliDeprecationWarning, - stacklevel=2, - ) resolved_use_utc = legacy_use_utc == "1" self.use_utc = resolved_use_utc self.use_color = use_color diff --git a/tests/test_logging.py b/tests/test_logging.py index 3a85c01..b7c4e6c 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -127,10 +127,13 @@ def test_configure_logger_honors_namespaced_log_utc_and_precedence(self) -> None stream = io.StringIO() with mock.patch.dict(os.environ, {"BASE_CLI_LOG_UTC": "1", "LOG_UTC": "0"}): - logger = base_cli.configure_logger("namespaced-utc-stream", None, debug=False, stream=stream) - logger.info("hello utc") + with warnings.catch_warnings(record=True) as caught: + warnings.simplefilter("always", base_cli.BaseCliDeprecationWarning) + logger = base_cli.configure_logger("namespaced-utc-stream", None, debug=False, stream=stream) + logger.info("hello utc") self.assertRegex(stream.getvalue(), r"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2} UTC INFO") + self.assertEqual(len(caught), 1) def test_legacy_log_utc_emits_deprecation_warning(self) -> None: with mock.patch.dict(os.environ, {"LOG_UTC": "1"}, clear=True): @@ -141,6 +144,21 @@ def test_legacy_log_utc_emits_deprecation_warning(self) -> None: self.assertEqual(len(caught), 1) self.assertIn("BASE_CLI_LOG_UTC", str(caught[0].message)) + def test_empty_legacy_log_utc_does_not_warn(self) -> None: + with mock.patch.dict(os.environ, {"LOG_UTC": ""}, clear=True): + with warnings.catch_warnings(record=True) as caught: + warnings.simplefilter("always", base_cli.BaseCliDeprecationWarning) + CliFormatter() + + self.assertEqual(caught, []) + + def test_deprecation_warning_respects_an_explicit_error_filter(self) -> None: + with mock.patch.dict(os.environ, {"LOG_UTC": "1"}, clear=True): + with warnings.catch_warnings(): + warnings.simplefilter("error", base_cli.BaseCliDeprecationWarning) + with self.assertRaises(base_cli.BaseCliDeprecationWarning): + CliFormatter() + def test_configure_logger_colors_python_user_stream_when_requested(self) -> None: stream = self._TtyStream() From 89c71ece67f1dbb5aee5bf0d087296e65a21088e Mon Sep 17 00:00:00 2001 From: Ramesh Padmanabhaiah <22363102+codeforester@users.noreply.github.com> Date: Sat, 3 Oct 2026 00:54:28 +0530 Subject: [PATCH 3/3] ci: separate sustained persistence cost from hosted filesystem tails --- docs/performance.md | 12 +++++++++++- scripts/benchmark_runtime.py | 9 +++++++-- tests/test_benchmark_runtime.py | 12 ++++++++++++ 3 files changed, 30 insertions(+), 3 deletions(-) diff --git a/docs/performance.md b/docs/performance.md index 8195656..96e0797 100644 --- a/docs/performance.md +++ b/docs/performance.md @@ -63,7 +63,7 @@ scheduler outlier block a change. | Cold no-op invocation, including startup and dispatch | 2,000 ms | 2,000 ms | 4,000 ms | 4,000 ms | | Base-cli lifecycle increment over Click warm dispatch | 5 ms | 5 ms | 15 ms | 15 ms | | Warm invocation and non-persistence feature scenarios | 50 ms | 50 ms | 100 ms | 100 ms | -| File-persistence-enabled scenario | 50 ms | 50 ms | 250 ms | 50 ms | +| File-persistence-enabled scenario | 125 ms | 125 ms | 250 ms | 50 ms | An initial 31-sample local calibration on macOS (Python 3.14.6, Apple Silicon) measured approximately 101 ms for base-cli cold import, 0.56 ms for warm @@ -76,6 +76,16 @@ budget instead of weakening other warm-scenario gates. These measurements are CI calibration evidence, not adoption claims or release comparisons; review subsequent retained artifacts before tightening platform budgets. +October 2026 hosted recalibration separates sustained persistence cost from +filesystem tails on Unix/macOS: median must remain at most **50 ms** and p95 +at most **125 ms**. The previous 50 ms p95 cap repeatedly rejected otherwise +unchanged runtime code, including the validation-only PR. Observed pairs were +14.66/118.04 ms (Unix median/p95) and 24.93/61.93 and 26.12/87.37 ms (macOS). +Evidence: [Unix run](https://github.com/basefoundry/base-cli/actions/runs/37048785893) +and [macOS validation-only run](https://github.com/basefoundry/base-cli/actions/runs/37052368353). +A sustained slowdown over 50 ms still fails; p95 over 125 ms also fails. +Windows, WSL, parser, import, and non-persistence limits are unchanged. + Each report is versioned as `base-cli.benchmark` schema version 1 and contains the package version, source revision, UTC timestamp, platform profile, Python version/ABI, OS release, architecture, CPU count, sample count, medians, p95, diff --git a/scripts/benchmark_runtime.py b/scripts/benchmark_runtime.py index 24f3e78..f5ade65 100755 --- a/scripts/benchmark_runtime.py +++ b/scripts/benchmark_runtime.py @@ -48,8 +48,8 @@ "wsl": 100.0, } PERSISTENCE_ENABLED_P95_BUDGETS_MS = { - "unix": 50.0, - "macos": 50.0, + "unix": 125.0, + "macos": 125.0, "windows": 250.0, "wsl": 50.0, } @@ -331,6 +331,11 @@ def _check_results(results: dict[str, FrameworkMetrics]) -> list[str]: feature_budget = _feature_budget_for_platform(name, BENCHMARK_PLATFORM) if p95 is not None and p95 > feature_budget: failures.append(f"base-cli {name} p95 exceeded {feature_budget:.0f} ms") + if BENCHMARK_PLATFORM in {"unix", "macos"} and isinstance(features, dict): + persistence = features.get("persistence_enabled_ms", {}) + median = persistence.get("median") if isinstance(persistence, dict) else None + if not isinstance(median, (int, float)) or not 0 <= median <= 50.0: + failures.append("base-cli persistence_enabled_ms median is missing, invalid, or exceeded 50 ms") return failures diff --git a/tests/test_benchmark_runtime.py b/tests/test_benchmark_runtime.py index 8528e5e..7518e06 100644 --- a/tests/test_benchmark_runtime.py +++ b/tests/test_benchmark_runtime.py @@ -125,6 +125,18 @@ def test_windows_persistence_budget_rejects_material_regressions(self) -> None: self.assertTrue(any("persistence_enabled_ms p95 exceeded 250 ms" in failure for failure in failures)) + def test_persistence_budget_separates_sustained_cost_from_filesystem_tails(self) -> None: + for profile in ("unix", "macos"): + for median, p95, fails in ((26.0, 118.0, False), (51.0, 60.0, True), (26.0, 126.0, True)): + with self.subTest(profile=profile, median=median, p95=p95): + metrics = self._complete_results() + sample = self._summary(p95) + sample["median"] = median + metrics["base-cli"]["features"]["persistence_enabled_ms"] = sample + with mock.patch.object(benchmark_runtime, "BENCHMARK_PLATFORM", profile): + failures = benchmark_runtime._check_results(metrics) + self.assertEqual(any("persistence_enabled_ms" in failure for failure in failures), fails) + def test_github_summary_separates_lifecycle_overhead_from_parser(self) -> None: metrics = self._complete_results(lifecycle_p95=4.0, click_p95=1.5) report = {