From 1515323b25a3bd05920ed7858889495943329cb7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Felix=20M=C3=BCller?= Date: Sat, 21 Feb 2026 12:50:55 +0100 Subject: [PATCH] feat: add centralized structured logging setup --- src/scribae/brief.py | 5 +++ src/scribae/brief_cli.py | 2 ++ src/scribae/feedback.py | 5 +++ src/scribae/feedback_cli.py | 2 ++ src/scribae/idea.py | 5 +++ src/scribae/idea_cli.py | 3 +- src/scribae/logging_config.py | 48 +++++++++++++++++++++++++ src/scribae/main.py | 2 ++ src/scribae/meta.py | 5 +++ src/scribae/meta_cli.py | 2 ++ src/scribae/refine.py | 9 +++-- src/scribae/refine_cli.py | 2 ++ src/scribae/translate/pipeline.py | 5 +++ src/scribae/translate_cli.py | 3 +- src/scribae/write.py | 5 +++ src/scribae/write_cli.py | 2 ++ tests/unit/logging_config_test.py | 58 +++++++++++++++++++++++++++++++ tests/unit/main_test.py | 15 ++++++++ 18 files changed, 173 insertions(+), 5 deletions(-) create mode 100644 src/scribae/logging_config.py create mode 100644 tests/unit/logging_config_test.py diff --git a/src/scribae/brief.py b/src/scribae/brief.py index 9e07aaa..afeb67b 100644 --- a/src/scribae/brief.py +++ b/src/scribae/brief.py @@ -2,6 +2,7 @@ import asyncio import json +import logging import re from collections.abc import Callable from dataclasses import dataclass @@ -20,6 +21,8 @@ from .project import ProjectConfig from .prompts.brief import SYSTEM_PROMPT, PromptBundle, build_prompt_bundle +logger = logging.getLogger(__name__) + __all__ = [ # re-exports for tests and public API "NoteDetails", @@ -234,6 +237,7 @@ def generate_brief( language_detector: Callable[[str], str] | None = None, ) -> SeoBrief: """Run the LLM call and return a validated SeoBrief.""" + logger.debug("Generating brief with model '%s'", model_name) resolved_settings = settings or OpenAISettings.from_env() llm_agent: Agent[None, SeoBrief] = ( _create_agent(model_name, resolved_settings, temperature=temperature, top_p=top_p, seed=seed) @@ -274,6 +278,7 @@ def generate_brief( raise BriefLLMError(f"LLM request failed: {exc}") from exc _report(reporter, "LLM call complete, structured brief validated.") + logger.debug("Brief generation completed successfully") return brief diff --git a/src/scribae/brief_cli.py b/src/scribae/brief_cli.py index ef2d923..9045d68 100644 --- a/src/scribae/brief_cli.py +++ b/src/scribae/brief_cli.py @@ -9,6 +9,7 @@ from .brief import BriefingError from .cli_output import echo_info, is_quiet, secho_info from .llm import DEFAULT_MODEL_NAME +from .logging_config import setup_logging from .project import load_default_project, load_project @@ -170,6 +171,7 @@ def brief_command( ), ) -> None: """CLI handler for `scribae brief`.""" + setup_logging(verbose=verbose and not is_quiet()) _validate_output_options(out, json_output, dry_run=dry_run, idea_all=idea_all, out_dir=out_dir) if (idea or idea_all) and ideas is None: raise typer.BadParameter("--ideas is required when selecting ideas.", param_hint="--ideas") diff --git a/src/scribae/feedback.py b/src/scribae/feedback.py index cba81a4..abc2a66 100644 --- a/src/scribae/feedback.py +++ b/src/scribae/feedback.py @@ -2,6 +2,7 @@ import asyncio import json +import logging import re from collections.abc import Callable, Sequence from dataclasses import dataclass @@ -21,6 +22,8 @@ from .prompts.feedback import FEEDBACK_SYSTEM_PROMPT, FeedbackPromptBundle, build_feedback_prompt_bundle from .prompts.feedback_categories import CATEGORY_DEFINITIONS +logger = logging.getLogger(__name__) + # Pattern to match emoji characters across common Unicode ranges _EMOJI_PATTERN = re.compile( "[" @@ -366,6 +369,7 @@ def generate_feedback_report( language_detector: Callable[[str], str] | None = None, ) -> FeedbackReport: """Generate the structured feedback report via the LLM.""" + logger.debug("Generating feedback report with model '%s'", model_name) prompts = prompts or build_prompt_bundle(context) resolved_settings = OpenAISettings.from_env() @@ -402,6 +406,7 @@ def generate_feedback_report( # Remap any out-of-scope categories to "other" report = _normalize_finding_categories(report, context.focus) + logger.debug("Feedback report generation completed successfully") return report diff --git a/src/scribae/feedback_cli.py b/src/scribae/feedback_cli.py index 747bcb9..88953f3 100644 --- a/src/scribae/feedback_cli.py +++ b/src/scribae/feedback_cli.py @@ -23,6 +23,7 @@ save_prompt_artifacts, ) from .llm import DEFAULT_MODEL_NAME +from .logging_config import setup_logging from .project import load_default_project, load_project @@ -141,6 +142,7 @@ def feedback_command( scribae feedback --body draft.md --brief brief.json --format json --out feedback.json scribae feedback --body draft.md --brief brief.json --section 1..3 --focus seo """ + setup_logging(verbose=verbose and not is_quiet()) reporter = (lambda msg: typer.secho(msg, err=True)) if verbose and not is_quiet() else None try: diff --git a/src/scribae/idea.py b/src/scribae/idea.py index c3e59d2..e4bb8a8 100644 --- a/src/scribae/idea.py +++ b/src/scribae/idea.py @@ -2,6 +2,7 @@ import asyncio import json +import logging import re from collections.abc import Callable from dataclasses import dataclass @@ -25,6 +26,8 @@ from .project import ProjectConfig from .prompts.idea import IDEA_SYSTEM_PROMPT, IdeaPromptBundle, build_idea_prompt_bundle +logger = logging.getLogger(__name__) + class IdeaError(Exception): """Raised when ideas cannot be generated.""" @@ -151,6 +154,7 @@ def generate_ideas( language_detector: Callable[[str], str] | None = None, ) -> IdeaList: """Run the LLM call and return validated ideas.""" + logger.debug("Generating ideas with model '%s'", model_name) resolved_settings = settings or OpenAISettings.from_env() llm_agent: Agent[None, IdeaList] = ( @@ -189,6 +193,7 @@ def generate_ideas( raise IdeaLLMError(f"LLM request failed: {exc}") from exc _report(reporter, "LLM call complete, ideas validated.") + logger.debug("Idea generation completed successfully") return ideas diff --git a/src/scribae/idea_cli.py b/src/scribae/idea_cli.py index ad4f1ff..2518218 100644 --- a/src/scribae/idea_cli.py +++ b/src/scribae/idea_cli.py @@ -7,6 +7,7 @@ from .cli_output import echo_info, is_quiet, secho_info from .idea import IdeaError, generate_ideas, prepare_context, render_json, save_prompt_artifacts from .llm import DEFAULT_MODEL_NAME +from .logging_config import setup_logging from .project import load_default_project, load_project @@ -122,7 +123,7 @@ def idea_command( ), ) -> None: """CLI handler for `scribae idea`.""" - + setup_logging(verbose=verbose and not is_quiet()) _validate_output_options(out, json_output, dry_run=dry_run) reporter = (lambda msg: typer.secho(msg, err=True)) if verbose and not is_quiet() else None diff --git a/src/scribae/logging_config.py b/src/scribae/logging_config.py new file mode 100644 index 0000000..ef30937 --- /dev/null +++ b/src/scribae/logging_config.py @@ -0,0 +1,48 @@ +from __future__ import annotations + +import logging +import os +import sys +from pathlib import Path + +_LOGGER_NAME = "scribae" + + +def setup_logging(*, verbose: bool = False, log_file: Path | None = None) -> logging.Logger: + """Configure Scribae logger handlers and level. + + Calling this function repeatedly is safe; existing handlers are replaced so + duplicate records are not emitted. + """ + + logger = logging.getLogger(_LOGGER_NAME) + logger.setLevel(logging.DEBUG if verbose else logging.INFO) + logger.propagate = False + + for handler in list(logger.handlers): + logger.removeHandler(handler) + + formatter = logging.Formatter("%(asctime)s %(name)s %(levelname)s %(message)s") + + stream_handler = logging.StreamHandler(sys.stderr) + stream_handler.setFormatter(formatter) + stream_handler.setLevel(logging.DEBUG if verbose else logging.WARNING) + logger.addHandler(stream_handler) + + resolved_log_file = log_file + if resolved_log_file is None: + raw_log_file = os.environ.get("SCRIBAE_LOG_FILE") + if raw_log_file: + resolved_log_file = Path(raw_log_file).expanduser() + + if resolved_log_file is not None: + resolved_log_file.parent.mkdir(parents=True, exist_ok=True) + file_handler = logging.FileHandler(resolved_log_file, encoding="utf-8") + file_handler.setFormatter(formatter) + file_handler.setLevel(logging.DEBUG if verbose else logging.INFO) + logger.addHandler(file_handler) + + return logger + + +__all__ = ["setup_logging"] diff --git a/src/scribae/main.py b/src/scribae/main.py index 8d9a8ff..6b13944 100644 --- a/src/scribae/main.py +++ b/src/scribae/main.py @@ -9,6 +9,7 @@ from .feedback_cli import feedback_command from .idea_cli import idea_command from .init_cli import init_command +from .logging_config import setup_logging from .meta_cli import meta_command from .refine_cli import refine_command from .translate_cli import translate_command @@ -42,6 +43,7 @@ def app_callback( ), ) -> None: """Root Scribae CLI callback.""" + setup_logging() ctx.obj = {"quiet": quiet} if no_color or "NO_COLOR" in os.environ: context = click.get_current_context(silent=True) diff --git a/src/scribae/meta.py b/src/scribae/meta.py index 27cc116..cd06f26 100644 --- a/src/scribae/meta.py +++ b/src/scribae/meta.py @@ -2,6 +2,7 @@ import asyncio import json +import logging import re from collections.abc import Callable from dataclasses import dataclass @@ -26,6 +27,8 @@ build_meta_prompt_bundle, ) +logger = logging.getLogger(__name__) + class MetaError(Exception): """Base class for meta-command failures.""" @@ -237,6 +240,7 @@ def generate_metadata( language_detector: Callable[[str], str] | None = None, ) -> ArticleMeta: """Generate final article metadata, calling the LLM when needed.""" + logger.debug("Generating metadata with overwrite mode '%s'", context.overwrite) prompts = prompts or build_prompt_bundle(context) needs_llm, reason = _needs_llm(context, force_llm_on_missing=force_llm_on_missing) @@ -291,6 +295,7 @@ def generate_metadata( merged.reading_time = context.body.reading_time merged.tags = _apply_allowed_tags(merged.tags, context.project.get("allowed_tags")) + logger.debug("Metadata generation completed successfully") return merged diff --git a/src/scribae/meta_cli.py b/src/scribae/meta_cli.py index c3b2a40..1334f3e 100644 --- a/src/scribae/meta_cli.py +++ b/src/scribae/meta_cli.py @@ -6,6 +6,7 @@ from .cli_output import echo_info, is_quiet, secho_info from .llm import DEFAULT_MODEL_NAME +from .logging_config import setup_logging from .meta import ( ArticleMeta, MetaBriefError, @@ -130,6 +131,7 @@ def meta_command( ), ) -> None: """CLI handler for `scribae meta`.""" + setup_logging(verbose=verbose and not is_quiet()) reporter = (lambda msg: typer.secho(msg, err=True)) if verbose and not is_quiet() else None try: diff --git a/src/scribae/refine.py b/src/scribae/refine.py index b5413a2..8f572c8 100644 --- a/src/scribae/refine.py +++ b/src/scribae/refine.py @@ -2,6 +2,7 @@ import asyncio import json +import logging import re from collections.abc import Callable, Sequence from dataclasses import dataclass @@ -27,6 +28,8 @@ Reporter = Callable[[str], None] | None +logger = logging.getLogger(__name__) + class RefiningError(Exception): """Base class for refine command failures.""" @@ -245,6 +248,7 @@ def refine_draft( language_detector: Callable[[str], str] | None = None, ) -> tuple[str, str | None]: """Refine a draft and optionally return a changelog.""" + logger.debug("Refining draft with model '%s'", model_name) draft = parse_draft(context.draft_text) outline = outline_sections(context.brief) refined_sections = _prepare_sections(draft, outline, preserve_anchors=preserve_anchors) @@ -336,6 +340,7 @@ def refine_draft( reporter=reporter, ) + logger.debug("Draft refinement completed successfully") return markdown, changelog_text @@ -514,9 +519,7 @@ def _prepare_sections( draft_section = draft.sections[index - 1] anchor = draft_section.anchor if preserve_anchors else None heading = _compose_heading(title, anchor=anchor) - refined_sections.append( - RefinedSection(index=index, title=title, heading=heading, body=draft_section.body) - ) + refined_sections.append(RefinedSection(index=index, title=title, heading=heading, body=draft_section.body)) if not refined_sections: raise RefiningValidationError("No outline sections selected.") return refined_sections diff --git a/src/scribae/refine_cli.py b/src/scribae/refine_cli.py index 900d051..ec6449c 100644 --- a/src/scribae/refine_cli.py +++ b/src/scribae/refine_cli.py @@ -6,6 +6,7 @@ from .cli_output import echo_info, is_quiet, secho_info from .llm import DEFAULT_MODEL_NAME +from .logging_config import setup_logging from .project import load_default_project, load_project from .refine import ( EvidenceMode, @@ -138,6 +139,7 @@ def refine_command( ), ) -> None: """CLI handler for `scribae refine`.""" + setup_logging(verbose=verbose and not is_quiet()) if dry_run and (out is not None or save_prompt is not None or changelog is not None): raise typer.BadParameter( "--dry-run cannot be combined with --out/--save-prompt/--changelog.", diff --git a/src/scribae/translate/pipeline.py b/src/scribae/translate/pipeline.py index db8fd08..f14031c 100644 --- a/src/scribae/translate/pipeline.py +++ b/src/scribae/translate/pipeline.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging from collections.abc import Callable from dataclasses import dataclass, field from typing import Any @@ -12,6 +13,8 @@ DebugCallback = Callable[[dict[str, Any]], None] | None +logger = logging.getLogger(__name__) + @dataclass class ToneProfile: @@ -73,6 +76,7 @@ def _report_block( self._report(f"{prefix}: {message}") def translate(self, text: str, cfg: TranslationConfig) -> str: + logger.debug("Starting translation pipeline: %s -> %s", cfg.source_lang, cfg.target_lang) self._report(f"Starting translation: {cfg.source_lang} -> {cfg.target_lang}") self._report("Segmenting markdown into blocks...") blocks = self.segmenter.segment(text) @@ -81,6 +85,7 @@ def translate(self, text: str, cfg: TranslationConfig) -> str: self._report("Reconstructing translated document...") result = self.segmenter.reconstruct(translated_blocks) self._report("Translation complete") + logger.debug("Translation pipeline completed") return result def translate_blocks(self, blocks: list[TextBlock], cfg: TranslationConfig) -> list[TextBlock]: diff --git a/src/scribae/translate_cli.py b/src/scribae/translate_cli.py index 3783632..e7cc3c6 100644 --- a/src/scribae/translate_cli.py +++ b/src/scribae/translate_cli.py @@ -14,6 +14,7 @@ from scribae.cli_output import echo_info, is_quiet, secho_info from scribae.language import LanguageResolutionError, detect_language, normalize_language from scribae.llm import DEFAULT_MODEL_NAME +from scribae.logging_config import setup_logging from scribae.project import load_default_project, load_project from scribae.translate import ( LLMPostEditor, @@ -60,7 +61,6 @@ def _configure_library_logging() -> None: pass - def _load_glossary(path: Path | None) -> dict[str, str]: if path is None: return {} @@ -205,6 +205,7 @@ def translate( ), ) -> None: """Translate a Markdown file using offline MT + local post-edit.""" + setup_logging(verbose=verbose and not is_quiet()) reporter = (lambda msg: typer.secho(msg, err=True)) if verbose and not is_quiet() else None _configure_library_logging() diff --git a/src/scribae/write.py b/src/scribae/write.py index 9af55b4..2237eb7 100644 --- a/src/scribae/write.py +++ b/src/scribae/write.py @@ -2,6 +2,7 @@ import asyncio import json +import logging import re from collections.abc import Callable, Sequence from dataclasses import dataclass @@ -27,6 +28,8 @@ from .prompts.write import SYSTEM_PROMPT, build_faq_prompt, build_user_prompt from .snippets import SnippetSelection, build_snippet_block +logger = logging.getLogger(__name__) + class WritingError(Exception): """Base class for write command failures.""" @@ -228,6 +231,7 @@ def generate_article( ) -> str: """Generate the Markdown body for the requested sections.""" sections = outline_sections(context.brief, section_range=section_range) + logger.debug("Generating article with %d sections", len(sections)) if save_prompt_dir is not None: try: save_prompt_dir.mkdir(parents=True, exist_ok=True) @@ -300,6 +304,7 @@ def generate_article( faq_body, ) + logger.debug("Article generation completed successfully") return article diff --git a/src/scribae/write_cli.py b/src/scribae/write_cli.py index 68d49c1..5803878 100644 --- a/src/scribae/write_cli.py +++ b/src/scribae/write_cli.py @@ -6,6 +6,7 @@ from .cli_output import echo_info, is_quiet, secho_info from .llm import DEFAULT_MODEL_NAME +from .logging_config import setup_logging from .project import load_default_project, load_project from .write import ( EvidenceMode, @@ -121,6 +122,7 @@ def write_command( ), ) -> None: """CLI handler for `scribae write`.""" + setup_logging(verbose=verbose and not is_quiet()) if dry_run and (out is not None or save_prompt is not None): raise typer.BadParameter("--dry-run cannot be combined with --out/--save-prompt.", param_hint="--dry-run") diff --git a/tests/unit/logging_config_test.py b/tests/unit/logging_config_test.py new file mode 100644 index 0000000..1d364e9 --- /dev/null +++ b/tests/unit/logging_config_test.py @@ -0,0 +1,58 @@ +from __future__ import annotations + +import logging +from pathlib import Path + +from scribae.logging_config import setup_logging + + +def _reset_scribae_logger() -> logging.Logger: + logger = logging.getLogger("scribae") + for handler in list(logger.handlers): + logger.removeHandler(handler) + return logger + + +def test_setup_logging_defaults_to_info_with_warning_stream_handler() -> None: + _reset_scribae_logger() + + logger = setup_logging() + + assert logger.level == logging.INFO + assert len(logger.handlers) == 1 + assert isinstance(logger.handlers[0], logging.StreamHandler) + assert logger.handlers[0].level == logging.WARNING + + +def test_setup_logging_verbose_enables_debug_level() -> None: + _reset_scribae_logger() + + logger = setup_logging(verbose=True) + + assert logger.level == logging.DEBUG + assert any(handler.level == logging.DEBUG for handler in logger.handlers) + + +def test_setup_logging_can_write_to_file(tmp_path: Path) -> None: + _reset_scribae_logger() + log_file = tmp_path / "scribae.log" + + logger = setup_logging(log_file=log_file) + logger.info("hello logging") + for handler in logger.handlers: + handler.flush() + + assert log_file.exists() + assert "hello logging" in log_file.read_text(encoding="utf-8") + + +def test_setup_logging_is_idempotent_for_handlers(tmp_path: Path) -> None: + _reset_scribae_logger() + log_file = tmp_path / "scribae.log" + + logger = setup_logging(log_file=log_file) + first = len(logger.handlers) + logger = setup_logging(log_file=log_file) + second = len(logger.handlers) + + assert first == second diff --git a/tests/unit/main_test.py b/tests/unit/main_test.py index e080a1e..d389c59 100644 --- a/tests/unit/main_test.py +++ b/tests/unit/main_test.py @@ -202,6 +202,21 @@ def test_version_command_outputs_version() -> None: assert result.stdout == f"scribae v{__version__}\n" +def test_app_callback_initializes_logging(monkeypatch: pytest.MonkeyPatch) -> None: + calls: list[dict[str, object]] = [] + + def _fake_setup_logging(**kwargs: object) -> object: + calls.append(dict(kwargs)) + return object() + + monkeypatch.setattr("scribae.main.setup_logging", _fake_setup_logging) + + result = runner.invoke(app, ["version"]) + + assert result.exit_code == 0 + assert calls == [{}] + + def test_help_flag_alias_outputs_help() -> None: result = runner.invoke(app, ["-h"])