Skip to content

Commit 701c144

Browse files
authored
fix(logging): suppress verbose log pollution in build plugins and remove handlers when disabled
This pull request resolves verbose logging output and terminal pollution when building and installing packages utilizing the `git-versioned` backend plugins. ### Key Changes - **Silence Build Plugins:** Enforced `clear_loggers=True` and adjusted the default logger settings to `level="WARNING"` (down from `INFO`) within the Hatchling, Setuptools, and Maturin plugins. - **Dangling Handlers Disposal:** Updated `configure_logger` to safely call `logger.remove()` on the active handler and reset the internal handler ID to `None` if logging is disabled. - **Log Demotion on Fallbacks:** Demoted failed tag and archive resolution logs from `warning` to `info` within version source resolution. This avoids false warning messages when the tool falls back to other resolved sources. - **Enhanced Test Suites:** Added target regression tests to cover cleanup of logging handlers and adapted E2E tests to verify silence during build operations under normal circumstances, alongside manual log injection flags. ## Type of Change - [x] Bug fix (non-breaking change which fixes an issue) - [ ] New feature (non-breaking change which adds functionality) - [ ] Breaking change (fix or feature that would cause existing functionality to not work as expected) - [ ] Documentation update (changes to `README.md`, `SUPPORT.md`, docstrings, etc.) - [x] Maintenance/Refactoring (non-breaking change that improves code structure or quality) ## Test Plan All changes have been validated by running the local Python test suites through Hatch. ### Automated Test Execution Run the unit, integration, and E2E regression tests using Hatch: ```bash # Execute functional test suite (unit + integration tests) .venv/bin/hatch run python:tests-func # Execute E2E plugin and CLI integration test suite .venv/bin/hatch run python:tests-e2e ``` ### Results - `tests-func` successfully executed **836 tests** (all PASSED). - `tests-e2e` successfully executed **211 tests** (all PASSED). ## Related Issues - Fixes #None ## Screenshots / Visuals (if applicable) N/A ## Use of AI - [ ] Includes AI-assisted code completion - [x] Includes code generated by an AI application - [x] Includes AI-generated tests ## Checklist > [!IMPORTANT] > Please review and complete this checklist before submitting your PR. This helps our maintainers process your contribution faster and ensures it meets the quality standards. - [x] "I certify that all code in this PR is my own, except as noted below." - [x] I have read the [CONTRIBUTING.md](../CONTRIBUTING.md) guide. - [x] My code follows the established style guidelines. - [x] I have performed a self-review of my own code. - [x] I have commented my code, particularly in hard-to-understand areas. - [x] I have made corresponding changes to the documentation. - [x] My changes generate no new warnings or errors. - [x] I have added tests that prove my fix is effective or that my feature works. - [x] New and existing unit tests pass locally with my changes.
1 parent c7f131c commit 701c144

9 files changed

Lines changed: 64 additions & 22 deletions

File tree

src/gitversioned/__init__.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -56,6 +56,6 @@
5656
"resolve_version_output_to_stream",
5757
]
5858

59-
__version__ = "0.2.1.dev25+02d93d4"
59+
__version__ = "0.3.1.dev25+652050a"
6060

6161
configure_logger()

src/gitversioned/logging.py

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -186,6 +186,10 @@ def configure_logger( # noqa: C901, PLR0912, PLR0915
186186
if not settings.enabled:
187187
logger.disable("gitversioned")
188188
intercept_standard_logging(False)
189+
if isinstance(_state["handler_id"], int):
190+
with contextlib.suppress(ValueError):
191+
logger.remove(_state["handler_id"])
192+
_state["handler_id"] = None
189193
return
190194

191195
logger.enable("gitversioned")

src/gitversioned/plugins/hatchling_plugin.py

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -90,7 +90,8 @@ def get_version_data(self) -> dict[str, str]:
9090
"""
9191
configure_logger(
9292
enabled=True,
93-
level="INFO",
93+
clear_loggers=True,
94+
level="WARNING",
9495
otel_formatting="disable",
9596
enqueue=False,
9697
format="<cyan>[gitversioned:hatch]</cyan> <level>{message}</level>\n",
@@ -277,7 +278,8 @@ def initialize(self, version: str, build_data: dict[str, Any]) -> None: # noqa:
277278
"""
278279
configure_logger(
279280
enabled=True,
280-
level="INFO",
281+
clear_loggers=True,
282+
level="WARNING",
281283
otel_formatting="disable",
282284
enqueue=False,
283285
format="<cyan>[gitversioned:hatch-build]</cyan> <level>{message}</level>\n",

src/gitversioned/plugins/maturin_plugin.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -257,7 +257,7 @@ def _get_maturin() -> types.ModuleType:
257257
configure_logger(
258258
enabled=True,
259259
clear_loggers=True,
260-
level="INFO",
260+
level="WARNING",
261261
otel_formatting="auto",
262262
filter=False,
263263
enqueue=True,

src/gitversioned/plugins/setuptools_plugin.py

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -62,7 +62,8 @@ def setup_keywords(distribution: Distribution, attribute: str, value: Any) -> No
6262
"""
6363
configure_logger(
6464
enabled=True,
65-
level="INFO",
65+
clear_loggers=True,
66+
level="WARNING",
6667
otel_formatting="disable",
6768
enqueue=False,
6869
format="[gitversioned:setuptools] {level} - {message}\n",
@@ -105,7 +106,8 @@ def finalize_distribution_options(distribution: Distribution) -> None:
105106
"""
106107
configure_logger(
107108
enabled=True,
108-
level="INFO",
109+
clear_loggers=True,
110+
level="WARNING",
109111
otel_formatting="disable",
110112
enqueue=False,
111113
format="[gitversioned:setuptools] {level} - {message}\n",

src/gitversioned/versioning/sources.py

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -363,7 +363,7 @@ def resolve_from_git_source(
363363
version = _extract_versions(patterns, text)[0]
364364
matches.append((version, reference))
365365
except VersionResolutionError as ver_err:
366-
logger.warning(
366+
logger.info(
367367
f"Could not extract version from git {type_} '{text}' using "
368368
f"patterns {patterns}: {ver_err}"
369369
)
@@ -452,7 +452,7 @@ def resolve_sources_from_archive(
452452
versions = _extract_versions(pattern, attr_val)
453453
break
454454
except ValueError:
455-
logger.warning(f"Could not extract version from {source}: {reference}")
455+
logger.info(f"Could not extract version from {source}: {reference}")
456456

457457
if not versions:
458458
raise VersionResolutionError(

tests/e2e/test_logging_stories.py

Lines changed: 22 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -389,9 +389,20 @@ def test_hatch_stderr_routing_and_format(
389389
:param valid_instances: Injected shared context fixture.
390390
"""
391391
repo_helper = valid_instances["repo"]
392+
repo_helper.tag("v0.1.0")
392393
clean_dist(repo_helper.path)
394+
395+
# 1. By default, INFO/DEBUG logs should be silent and not pollute stderr
393396
result = run_build(repo_helper.path)
394397
assert result.returncode == 0
398+
assert "[gitversioned:hatch]" not in result.stderr
399+
assert "[gitversioned:hatch]" not in result.stdout
400+
401+
# 2. When explicitly configured at INFO level, logs should be routed to stderr and match format
402+
clean_dist(repo_helper.path)
403+
env = {"GITVERSIONED__LOGGING__LEVEL": "INFO"}
404+
result = run_build(repo_helper.path, env=env)
405+
assert result.returncode == 0
395406
# Logs should not pollute stdout
396407
assert "[gitversioned:hatch]" not in result.stdout
397408
# Logs must go to stderr and match the default hatch prefix
@@ -424,7 +435,7 @@ def test_hatch_verbose_downgrade(self, valid_instances: dict[str, Any]) -> None:
424435
@pytest.mark.regression
425436
def test_hatch_protect_native_sinks(self, valid_instances: dict[str, Any]) -> None:
426437
"""
427-
Assert Hatchling plugin preserves existing sinks by enforcing clear_loggers=False (AC 2.4).
438+
Assert Hatchling plugin clears existing sinks by enforcing clear_loggers=True (AC 2.4).
428439
429440
:param valid_instances: Injected shared context fixture.
430441
"""
@@ -439,9 +450,8 @@ def test_hatch_protect_native_sinks(self, valid_instances: dict[str, Any]) -> No
439450
source = GitVersionedVersionSource("{str(repo_helper.path)}", {{}})
440451
source.get_version_data()
441452
442-
# Pre-existing loguru handlers should not be cleared, so parent_logs collects the plugin output
443-
assert len(parent_logs) > 0
444-
assert any("get_version_data called" in msg or "gitversioned computed version" in msg for msg in parent_logs)
453+
# Pre-existing loguru handlers should be cleared by default, so parent_logs should be empty
454+
assert len(parent_logs) == 0
445455
print("SUCCESS")
446456
"""
447457

@@ -583,12 +593,12 @@ def test_setuptools_root_interception(
583593
from gitversioned.plugins.setuptools_plugin import finalize_distribution_options
584594
from setuptools import Distribution
585595
586-
captured = []
587-
logger.add(captured.append, format="{message}")
588-
589596
dist = Distribution({"name": "test_pkg", "version": "0.0.0"})
590597
finalize_distribution_options(dist)
591598
599+
captured = []
600+
logger.add(captured.append, format="{message}")
601+
592602
# Verify handler injection
593603
root_logger = logging.getLogger()
594604
assert any(type(h).__name__ == "InterceptHandler" for h in root_logger.handlers)
@@ -609,12 +619,14 @@ def test_setuptools_protect_sinks_and_format(
609619
self, valid_instances: dict[str, Any]
610620
) -> None:
611621
"""
612-
Assert clear_loggers=False preserves sinks and format matches tag layout (AC 3.3, 3.4).
622+
Assert clear_loggers=True removes pre-existing sinks and format matches tag layout (AC 3.3, 3.4).
613623
614624
:param valid_instances: Injected shared context fixture.
615625
"""
616626
valid_instances["repo"]
617627
snippet = """
628+
import os
629+
os.environ["GITVERSIONED__LOGGING__LEVEL"] = "INFO"
618630
from loguru import logger
619631
from gitversioned.plugins.setuptools_plugin import finalize_distribution_options
620632
from setuptools import Distribution
@@ -625,9 +637,8 @@ def test_setuptools_protect_sinks_and_format(
625637
dist = Distribution({"name": "test_pkg", "version": "0.0.0"})
626638
finalize_distribution_options(dist)
627639
628-
# Verification 1: Parent sinks preserved
629-
assert len(parent_logs) > 0
630-
assert any("Finalizing distribution options" in msg or "Resolving version sources" in msg for msg in parent_logs)
640+
# Verification 1: Parent sinks cleared
641+
assert len(parent_logs) == 0
631642
print("SUCCESS")
632643
"""
633644
result = run_python_snippet(snippet)

tests/python/integration/test_logging.py

Lines changed: 16 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -634,6 +634,16 @@ def log_worker(thread_index: int) -> None:
634634
logger.remove()
635635
_state["handler_id"] = original_handler_id
636636

637+
@pytest.mark.regression
638+
def test_configure_logger_removes_handler_when_disabled(self) -> None:
639+
"""Verify configure_logger removes the previously registered handler when disabling."""
640+
_state["handler_id"] = 777
641+
settings_instance = LoggingSettings(enabled=False)
642+
with patch("gitversioned.logging.logger") as mock_loguru:
643+
configure_logger(settings_instance)
644+
mock_loguru.remove.assert_called_once_with(777)
645+
assert _state["handler_id"] is None
646+
637647

638648
class TestCLIEntrypoint:
639649
"""Integration test suite for logger behavior under CLI execution context."""
@@ -676,7 +686,8 @@ def test_plugin_logger_setup(self, tmp_path: Path) -> None:
676686
assert mock_configure.call_count == 1
677687
call_kwargs = mock_configure.call_args.kwargs
678688
assert call_kwargs["enabled"] is True
679-
assert call_kwargs["level"] == "INFO"
689+
assert call_kwargs["clear_loggers"] is True
690+
assert call_kwargs["level"] == "WARNING"
680691
assert call_kwargs["otel_formatting"] == "disable"
681692
assert call_kwargs["enqueue"] is False
682693

@@ -699,7 +710,8 @@ def test_plugin_logger_setup(self, tmp_path: Path) -> None:
699710
assert mock_configure.call_count == 1
700711
call_kwargs = mock_configure.call_args.kwargs
701712
assert call_kwargs["enabled"] is True
702-
assert call_kwargs["level"] == "INFO"
713+
assert call_kwargs["clear_loggers"] is True
714+
assert call_kwargs["level"] == "WARNING"
703715
assert call_kwargs["otel_formatting"] == "disable"
704716
assert call_kwargs["enqueue"] is False
705717

@@ -714,7 +726,8 @@ def test_plugin_logger_setup(self, tmp_path: Path) -> None:
714726
assert mock_configure.call_count == 1
715727
call_kwargs = mock_configure.call_args.kwargs
716728
assert call_kwargs["enabled"] is True
717-
assert call_kwargs["level"] == "INFO"
729+
assert call_kwargs["clear_loggers"] is True
730+
assert call_kwargs["level"] == "WARNING"
718731
assert call_kwargs["otel_formatting"] == "disable"
719732
assert call_kwargs["enqueue"] is False
720733

tests/python/unit/test_logging.py

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -614,6 +614,16 @@ def test_invocation_clear_loggers_real_logger(self) -> None:
614614
logger.remove()
615615
_state["handler_id"] = original_handler_id
616616

617+
@pytest.mark.regression
618+
def test_configure_logger_removes_handler_when_disabled(self) -> None:
619+
"""Verify configure_logger removes the previously registered handler when disabling."""
620+
_state["handler_id"] = 9999
621+
settings = LoggingSettings(enabled=False)
622+
with patch("gitversioned.logging.logger") as mock_logger:
623+
configure_logger(settings)
624+
mock_logger.remove.assert_called_once_with(9999)
625+
assert _state["handler_id"] is None
626+
617627

618628
class TestAutolog:
619629
"""Test suite for autolog module-level decorator."""

0 commit comments

Comments
 (0)