diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 15aae4b..df7de90 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -107,6 +107,14 @@ jobs: run: | python3.12 -m pytest tests/test_pr37_regression.py -v --tb=short + - name: Run topic07 logger regressions + run: | + python3.12 -m pytest \ + tests/test_logger.py \ + tests/test_logger_wiring.py \ + tests/test_topic07_logger_case_report.py \ + -v --tb=short + - name: Generate test visualization page if: github.ref == 'refs/heads/main' run: | @@ -218,6 +226,14 @@ jobs: --json benchmark_reports/const_merge_report.json \ --markdown benchmark_reports/const_merge_report.md + # ── 3.1.2 课题07：结构化日志 case 报告（A/B 输出一致 + 失败路径） ── + - name: Topic 07 logger case report + run: | + mkdir -p benchmark_reports + python3.12 benchmarks/run_topic07_logger_case.py \ + --json benchmark_reports/logger_report.json \ + --markdown benchmark_reports/logger_report.md + # ── 3.2 DSL 用例编译 + 模拟基准 ──────────────────────────────────── - name: DSL case compilation benchmarks run: | @@ -363,6 +379,9 @@ jobs: if [ -f benchmark_reports/const_merge_report.md ]; then cat benchmark_reports/const_merge_report.md >> $GITHUB_STEP_SUMMARY fi + if [ -f benchmark_reports/logger_report.md ]; then + cat benchmark_reports/logger_report.md >> $GITHUB_STEP_SUMMARY + fi echo "" >> $GITHUB_STEP_SUMMARY if [ -f benchmark_reports/github_summary.md ]; then cat benchmark_reports/github_summary.md >> $GITHUB_STEP_SUMMARY diff --git a/benchmarks/cases/topic07_logger_feature.dsl b/benchmarks/cases/topic07_logger_feature.dsl new file mode 100644 index 0000000..1d3c33b --- /dev/null +++ b/benchmarks/cases/topic07_logger_feature.dsl @@ -0,0 +1,9 @@ +# Structured-logging feature case (Topic 07). +# Deterministic loop + arithmetic chain. The case is deliberately small: +# parse / optimize / codegen / asm / emit all run on it, which is all the +# report needs to prove the staged log record and the byte-identical output. +for i = 0, 4 + acc = add(acc, x) +endfor +t = mul(acc, x) +return t diff --git a/benchmarks/run_topic07_logger_case.py b/benchmarks/run_topic07_logger_case.py new file mode 100644 index 0000000..0d30338 --- /dev/null +++ b/benchmarks/run_topic07_logger_case.py @@ -0,0 +1,549 @@ +#!/usr/bin/env python3 +"""Run one Topic 07 structured-logging feature case and emit auditable reports. + +The report proves five separate facts: + +1. compiling the deterministic case with structured logging enabled + (``CompilerConfig(use_logger=True, log_level="INFO", log_file=...)``) + succeeds and writes a staged log record covering every compiler phase; +2. the log file stays a complete DEBUG record while the console level is + INFO, and the compiler output is byte-for-byte identical to a run with + logging disabled (A/B output equality); +3. a syntax-error compile with logging enabled returns ``success=False`` + and still records an ERROR line without the process crashing; +4. an ``exc_info=True`` ERROR record renders its traceback into the log + file (the D1/D2 formatter contract, probed separately so it never + contaminates the compiler failure log); +5. repeated ``init_logger`` / ``shutdown`` cycles do not accumulate + handlers, and repeated compiles keep the handler count stable. + +This is a deterministic feature/integration case, not a real-workload +performance claim. The timing A/B is recorded for information only; no +threshold is enforced. +""" + +from __future__ import annotations + +import argparse +import hashlib +import json +import logging +import statistics +import tempfile +import time +from datetime import datetime, timezone +from pathlib import Path +from typing import Any + +from scratchv.compiler import CompilerConfig, CompilerDriver +from scratchv.utils.logger import ( + get_logger, + init_logger, + shutdown, +) + +SCHEMA_VERSION = "topic07-logger-case/1" +DEFAULT_CASE = ( + Path(__file__).parent / "cases" / "topic07_logger_feature.dsl" +) +DEFAULT_JSON = Path("benchmark_reports/logger_report.json") +DEFAULT_MARKDOWN = Path("benchmark_reports/logger_report.md") + +#: Console level used by the logged run. The file handler must stay at +#: DEBUG regardless, which is what hard check 4 verifies. +LOG_LEVEL = "INFO" +#: Common pipeline configuration for both A/B sides (CLI defaults). +BASE_CONFIG: dict[str, Any] = { + "optimize_level": "all", + "reg_alloc": "greedy", +} +OUTPUT_NAME = "feature_case.s" +#: Phase names this branch actually emits through ``log_phase`` / +#: ``log_progress``. ``compiler.passes`` is the PassManager progress logger +#: (``scratchv.compiler.passes``). +EXPECTED_PHASES = ( + "compiler.parse", + "compiler.optimize", + "compiler.passes", + "compiler.codegen", + "compiler.asm", + "compiler.emit", +) +LEVELS = ("DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL") +#: Deterministic syntax error: the DSL validator reports E101 before any +#: phase starts, so the driver must still log an ERROR summary. +FAILURE_SOURCE = "add(a, b\n" + + +def _one_line(text: str) -> str: + for line in text.splitlines(): + if line.strip(): + return line.strip() + return text + + +def _sha256_text(text: str) -> str: + return hashlib.sha256(text.encode("utf-8")).hexdigest() + + +def _sha256_file(path: Path) -> str: + if not path.is_file(): + return "" + return hashlib.sha256(path.read_bytes()).hexdigest() + + +def _handler_count() -> int: + return len(logging.getLogger("scratchv").handlers) + + +def _count_levels(text: str) -> dict[str, int]: + """Count records per level in a ``_PlainFormatter`` log file.""" + counts = {name: 0 for name in LEVELS} + for line in text.splitlines(): + parts = line.split() + if len(parts) >= 3 and parts[2] in counts: + counts[parts[2]] += 1 + return counts + + +def _phase_coverage(text: str) -> dict[str, bool]: + return { + phase: f"[scratchv.{phase}]" in text for phase in EXPECTED_PHASES + } + + +def _phase_records(text: str) -> dict[str, int]: + return { + phase: sum( + 1 for line in text.splitlines() + if f"[scratchv.{phase}]" in line + ) + for phase in EXPECTED_PHASES + } + + +def _debug_markers(text: str) -> dict[str, bool]: + """DEBUG-only lines that INFO console filtering must not remove.""" + return { + "config_line": "config: backend=" in text, + "parser_detail": "parser: extended-dsl" in text, + "pass_detail": "pass constant-folding:" in text, + "codegen_step": "-> instruction selection" in text, + } + + +def measure_logged_run( + case_path: Path, repeats: int, workdir: Path, +) -> dict[str, Any]: + """Compile *case_path* *repeats* times with logging enabled. + + A fresh driver per repeat reproduces one-compile-per-process usage and + exercises ``init_logger`` re-initialisation each time; the handler + count after every compile must stay at two (console + file). + """ + workdir.mkdir(parents=True, exist_ok=True) + log_path = workdir / "compiler.log" + output_path = workdir / OUTPUT_NAME + shutdown() + + result = None + times: list[float] = [] + handler_counts: list[int] = [] + for _ in range(repeats): + driver = CompilerDriver(CompilerConfig( + use_logger=True, + log_level=LOG_LEVEL, + log_file=str(log_path), + log_color=False, + **BASE_CONFIG, + )) + started = time.perf_counter() + result = driver.compile(str(case_path), str(output_path)) + times.append((time.perf_counter() - started) * 1000.0) + handler_counts.append(_handler_count()) + + log_text = ( + log_path.read_text(encoding="utf-8") if log_path.is_file() else "" + ) + data: dict[str, Any] = { + "enabled": True, + "success": bool(result and result.success), + "errors": [_one_line(e) for e in (result.errors[:3] if result else [])], + "runs": repeats, + "compile_ms_samples": times, + "compile_ms_median": statistics.median(times), + "output_bytes": len(result.output_text.encode()) if result else 0, + "output_sha256": _sha256_text(result.output_text) if result else "", + "output_file": str(output_path), + "output_file_sha256": _sha256_file(output_path), + "handler_counts": handler_counts, + "handler_count_after_compile": ( + handler_counts[-1] if handler_counts else 0 + ), + "log_file": str(log_path), + "log_file_exists": log_path.is_file(), + "log_file_bytes": len(log_text.encode("utf-8")), + "log_file_sha256": _sha256_text(log_text), + "levels": _count_levels(log_text), + "phases": _phase_coverage(log_text), + "phase_records": _phase_records(log_text), + "debug_markers": _debug_markers(log_text), + } + shutdown() + data["handler_count_after_shutdown"] = _handler_count() + return data + + +def measure_plain_run( + case_path: Path, repeats: int, workdir: Path, +) -> dict[str, Any]: + """Compile *case_path* *repeats* times without any logging configured.""" + workdir.mkdir(parents=True, exist_ok=True) + output_path = workdir / OUTPUT_NAME + shutdown() + + result = None + times: list[float] = [] + handler_counts: list[int] = [] + for _ in range(repeats): + driver = CompilerDriver(CompilerConfig(**BASE_CONFIG)) + started = time.perf_counter() + result = driver.compile(str(case_path), str(output_path)) + times.append((time.perf_counter() - started) * 1000.0) + handler_counts.append(_handler_count()) + shutdown() + + return { + "enabled": False, + "success": bool(result and result.success), + "errors": [_one_line(e) for e in (result.errors[:3] if result else [])], + "runs": repeats, + "compile_ms_samples": times, + "compile_ms_median": statistics.median(times), + "output_bytes": len(result.output_text.encode()) if result else 0, + "output_sha256": _sha256_text(result.output_text) if result else "", + "output_file": str(output_path), + "output_file_sha256": _sha256_file(output_path), + "handler_counts": handler_counts, + "handler_count_after_compile": ( + handler_counts[-1] if handler_counts else 0 + ), + } + + +def measure_failure_path(workdir: Path) -> dict[str, Any]: + """Compile a syntax-error DSL with logging enabled and inspect the log. + + The validator reports the syntax error before any phase starts, so the + driver returns ``success=False`` with an ERROR summary line. The + ``exc_info`` formatter contract is probed afterwards in a separate log + file so the compiler failure record stays uncontaminated. + """ + workdir.mkdir(parents=True, exist_ok=True) + bad_path = workdir / "bad.dsl" + bad_path.write_text(FAILURE_SOURCE, encoding="utf-8") + log_path = workdir / "failure.log" + probe_log_path = workdir / "exc_info_probe.log" + output_path = workdir / "bad.s" + shutdown() + + driver = CompilerDriver(CompilerConfig( + use_logger=True, + log_level=LOG_LEVEL, + log_file=str(log_path), + log_color=False, + **BASE_CONFIG, + )) + result = driver.compile(str(bad_path), str(output_path)) + shutdown() + + log_text = ( + log_path.read_text(encoding="utf-8") if log_path.is_file() else "" + ) + levels = _count_levels(log_text) + + init_logger(level=LOG_LEVEL, log_file=str(probe_log_path), + use_color=False) + try: + raise RuntimeError("exc_info probe") + except RuntimeError: + get_logger("probe.exc_info").error( + "exception formatting probe", exc_info=True, + ) + shutdown() + probe_text = ( + probe_log_path.read_text(encoding="utf-8") + if probe_log_path.is_file() else "" + ) + + return { + "success": bool(result.success), + "error_count": len(result.errors), + "first_error": _one_line(result.errors[0]) if result.errors else "", + "output_written": output_path.is_file(), + "log_file": str(log_path), + "log_file_exists": log_path.is_file(), + "log_file_bytes": len(log_text.encode("utf-8")), + "levels": levels, + "error_records": [ + line for line in log_text.splitlines() if " ERROR " in line + ], + "has_error_record": levels.get("ERROR", 0) > 0, + "exc_info_log_file": str(probe_log_path), + "exc_info_has_traceback": ( + "Traceback (most recent call last)" in probe_text + ), + "exc_info_has_runtime_error": "RuntimeError: exc_info probe" in ( + probe_text + ), + } + + +def measure_handler_lifecycle(workdir: Path) -> dict[str, Any]: + """Re-initialise the logger repeatedly and watch the handler count. + + Three console-only cycles give one handler each; three file cycles give + two (console + file) each. ``init_logger`` releases the previous + handlers, so the count must never grow and ``shutdown`` must reach 0. + """ + workdir.mkdir(parents=True, exist_ok=True) + shutdown() + counts: list[int] = [] + for _ in range(3): + init_logger(level=LOG_LEVEL, use_color=False) + counts.append(_handler_count()) + shutdown() + for i in range(3): + init_logger( + level=LOG_LEVEL, + log_file=str(workdir / f"cycle_{i}.log"), + use_color=False, + ) + counts.append(_handler_count()) + get_logger("lifecycle").debug("handler lifecycle probe %d", i) + shutdown() + after = _handler_count() + return { + "cycles": len(counts), + "handler_counts": counts, + "expected_handlers": {"console_only": 1, "console_and_file": 2}, + "max_handlers": max(counts) if counts else 0, + "after_shutdown": after, + "leaked": after != 0 or (bool(counts) and max(counts) > 2), + } + + +def evaluate(case_path: Path, repeats: int) -> dict[str, Any]: + """Build the full report payload and run the hard invariants.""" + with tempfile.TemporaryDirectory() as tmp: + workdir = Path(tmp) + logged = measure_logged_run(case_path, repeats, workdir / "logged") + plain = measure_plain_run(case_path, repeats, workdir / "plain") + failure = measure_failure_path(workdir / "failure") + lifecycle = measure_handler_lifecycle(workdir / "lifecycle") + + outputs_equal = ( + logged["success"] + and plain["success"] + and logged["output_sha256"] == plain["output_sha256"] + and logged["output_file_sha256"] == plain["output_file_sha256"] + and logged["output_bytes"] == plain["output_bytes"] + ) + overhead_ms = logged["compile_ms_median"] - plain["compile_ms_median"] + overhead_pct = ( + overhead_ms / plain["compile_ms_median"] * 100.0 + if plain["compile_ms_median"] else 0.0 + ) + + hard_checks = { + "case_compiles_with_logging": logged["success"], + "case_compiles_without_logging": plain["success"], + "log_file_created": ( + logged["log_file_exists"] and logged["log_file_bytes"] > 0 + ), + "log_file_contains_debug_records": ( + logged["levels"]["DEBUG"] > 0 + and all(logged["debug_markers"].values()) + ), + "log_file_records_all_phases": all(logged["phases"].values()), + "outputs_byte_identical": outputs_equal, + "failure_returns_unsuccessful": ( + not failure["success"] and failure["error_count"] > 0 + ), + "failure_log_has_error_record": failure["has_error_record"], + "exc_info_rendered_to_file": ( + failure["exc_info_has_traceback"] + and failure["exc_info_has_runtime_error"] + ), + "no_handler_leak_after_reinit": ( + not lifecycle["leaked"] + and logged["handler_count_after_shutdown"] == 0 + ), + } + failed = sorted(name for name, ok in hard_checks.items() if not ok) + + return { + "schema_version": SCHEMA_VERSION, + "topic": "topic07-logger", + "generated_at": datetime.now(timezone.utc).isoformat(), + "case": str(case_path), + "config": { + "use_logger": True, + "log_level": LOG_LEVEL, + "log_color": False, + **BASE_CONFIG, + }, + "runs": repeats, + "logged": logged, + "plain": plain, + "outputs_equal": outputs_equal, + "failure": failure, + "handler_lifecycle": lifecycle, + "overhead_ms": round(overhead_ms, 4), + "overhead_pct": round(overhead_pct, 2), + "hard_checks": hard_checks, + "hard_failures": failed, + "honesty": ( + "Deterministic feature case compiled by the repository's own " + "CompilerDriver. The timing A/B is wall-clock on a tiny case " + "and is recorded for information only; no threshold is " + "enforced. Output equality is byte-level (sha256) between the " + "logged and plain runs. The failure path is a DSL syntax " + "error reported by the validator, so its ERROR record carries " + "no traceback by design; the exc_info formatter contract is " + "probed separately through the public logger API. Handler " + "counts prove init_logger/shutdown do not accumulate handlers." + ), + } + + +def render_markdown(report: dict[str, Any]) -> str: + logged = report["logged"] + plain = report["plain"] + failure = report["failure"] + lifecycle = report["handler_lifecycle"] + checks = report["hard_checks"] + passed = len(checks) - len(report["hard_failures"]) + lines = [ + "# Topic 07 Structured-Logging Feature Case", + "", + f"- Schema: `{report['schema_version']}`", + f"- Case: `{report['case']}`", + f"- Generated: {report['generated_at']}", + f"- Config: log_level={report['config']['log_level']}, " + f"log_color={report['config']['log_color']}, " + f"optimize_level={report['config']['optimize_level']}, " + f"reg_alloc={report['config']['reg_alloc']}", + f"- Hard checks: " + f"{'PASS' if not report['hard_failures'] else 'FAIL'} " + f"({passed}/{len(checks)})", + "", + "## A/B summary", + "", + "| Metric | logging off | logging on | delta |", + "|--------|------------:|-----------:|------:|", + f"| Compile success | {plain['success']} | {logged['success']} | " + f"same |", + f"| Output bytes | {plain['output_bytes']} | " + f"{logged['output_bytes']} | " + f"{logged['output_bytes'] - plain['output_bytes']:+d} |", + f"| Output sha256 (first 12) | `{plain['output_sha256'][:12]}` | " + f"`{logged['output_sha256'][:12]}` | " + f"{'identical' if report['outputs_equal'] else 'DIFFERS'} |", + f"| Compile time (ms, median of {report['runs']}) | " + f"{plain['compile_ms_median']:.4f} | " + f"{logged['compile_ms_median']:.4f} | " + f"{report['overhead_ms']:+.4f} " + f"({report['overhead_pct']:+.1f}%) |", + f"| Handler count after compile | " + f"{plain['handler_count_after_compile']} | " + f"{logged['handler_count_after_compile']} | - |", + f"| Log file bytes | n/a | {logged['log_file_bytes']} | - |", + f"| DEBUG records in log | n/a | {logged['levels']['DEBUG']} | - |", + "", + "> Timing is wall-clock on a tiny deterministic case; it is " + "reported for information only (no pass/fail threshold).", + "", + "## Log phase coverage (logging on)", + "", + "| Phase | Present | Records |", + "|-------|---------|--------:|", + ] + for phase, present in logged["phases"].items(): + lines.append( + f"| `{phase}` | {'yes' if present else 'NO'} | " + f"{logged['phase_records'].get(phase, 0)} |" + ) + lines += [ + "", + "- Level counts: " + ", ".join( + f"{name}={count}" for name, count in logged["levels"].items() + ), + "- DEBUG-only markers: " + ", ".join( + f"{name}={'yes' if ok else 'NO'}" + for name, ok in logged["debug_markers"].items() + ), + "", + "## Failure path (syntax error, logging on)", + "", + f"- Compile success: {failure['success']} (expected False), " + f"errors: {failure['error_count']}", + f"- First error: `{failure['first_error']}`", + f"- ERROR records in log: {failure['levels']['ERROR']}", + f"- Log file: {failure['log_file_bytes']} bytes, " + f"exists={failure['log_file_exists']}", + f"- Output written: {failure['output_written']} (expected False)", + f"- exc_info formatter probe: " + f"traceback rendered={failure['exc_info_has_traceback']}, " + f"marker rendered={failure['exc_info_has_runtime_error']}", + "", + "## Handler lifecycle", + "", + f"- handler counts across re-inits: {lifecycle['handler_counts']}", + f"- max handlers: {lifecycle['max_handlers']} " + f"(console + file = 2)", + f"- handlers after shutdown: {lifecycle['after_shutdown']}", + f"- leaked: {lifecycle['leaked']}", + "", + "## Hard checks", + "", + ] + for name, ok in checks.items(): + lines.append(f"- [{'x' if ok else ' '}] {name}") + lines += [ + "", + "## Honesty", + "", + report["honesty"], + "", + ] + return "\n".join(lines) + + +def main(argv: list[str] | None = None) -> int: + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("--case", type=Path, default=DEFAULT_CASE) + parser.add_argument("--json", type=Path, default=DEFAULT_JSON) + parser.add_argument("--markdown", type=Path, default=DEFAULT_MARKDOWN) + parser.add_argument("--repeats", type=int, default=5) + args = parser.parse_args(argv) + if args.repeats < 1: + parser.error("--repeats must be positive") + if not args.case.is_file(): + parser.error(f"feature case not found: {args.case}") + + report = evaluate(args.case, args.repeats) + args.json.parent.mkdir(parents=True, exist_ok=True) + args.json.write_text(json.dumps(report, indent=2) + "\n") + args.markdown.parent.mkdir(parents=True, exist_ok=True) + args.markdown.write_text(render_markdown(report) + "\n") + print(render_markdown(report)) + if report["hard_failures"]: + print("HARD FAILURES: " + ", ".join(report["hard_failures"])) + return 1 + print(f"reports written: {args.json}, {args.markdown}") + return 0 + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git "a/docs/topics/07-\347\274\226\350\257\221\345\231\250\346\227\245\345\277\227\345\242\236\345\274\272\345\231\250-\345\274\200\345\217\221\346\226\207\346\241\243.md" "b/docs/topics/07-\347\274\226\350\257\221\345\231\250\346\227\245\345\277\227\345\242\236\345\274\272\345\231\250-\345\274\200\345\217\221\346\226\207\346\241\243.md" new file mode 100644 index 0000000..79fee24 --- /dev/null +++ "b/docs/topics/07-\347\274\226\350\257\221\345\231\250\346\227\245\345\277\227\345\242\236\345\274\272\345\231\250-\345\274\200\345\217\221\346\226\207\346\241\243.md" @@ -0,0 +1,638 @@ +# ScratchV 编译器日志增强器开发文档 + +> 文档版本：v1.1 +> 编写日期：2026-09-14 +> 关联设计文档：`设计文档.md`（同目录） +> 目标读者：实施本课题的工程师（或 AI Agent） +> 适用仓库：`/root/Lab/ScratchV`（锚点行号为 2026-09-14 实测，改动后会偏移，请以符号名定位） +> 修复轮次：2026-09-14 评审 `topic07-review` F1–F8 修订（根级别规则、失败路径 ERROR、日志路径防护、shutdown 复用、Pass 异常栈；本文档 §2.1/§2.2/§2.3/§五 已同步） + +--- + +## 一、接口契约（精确名称） + +### 1.1 Python API（`scratchv/utils/logger.py`） + +```python +def init_logger(level: str = "INFO", + log_file: str | None = None, + use_color: bool = True) -> None: ... + +def get_logger(name: str) -> logging.Logger: ... + +def set_level(level: str) -> None: ... + +def shutdown() -> None: ... + +@contextmanager +def log_phase(name: str, description: str = ""): ... + +def log_progress(name: str, current: int, total: int, description: str = "") -> None: ... + +def log_step(name: str, step_name: str) -> None: ... +``` + +- `init_logger` 公共签名**不变**，仅行为改为幂等（先关旧 handler）。 +- 新增模块私有状态（非公共 API）：`_console_handler: Optional[logging.Handler]`、`_file_handler: Optional[logging.Handler]`。 +- 合法级别字符串：`DEBUG` / `INFO` / `WARNING` / `ERROR` / `CRITICAL`（大小写不敏感，内部 `.upper()`）。 + +### 1.2 CLI 参数（`scratchv/main.py::build_arg_parser`） + +| 参数 | 类型 | 默认 | 判定 | +|------|------|------|------| +| `--log-level` | `{DEBUG,INFO,WARNING,ERROR,CRITICAL}` | `None` | **保留并修复**（补 `CRITICAL`；`None` = 日志关闭） | +| `--log-file` | `FILE` | `None` | **本期引入** | +| `--json-log` | — | — | **本期不引入**；保留名 `--json-log FILE`（JSON Lines 写文件，禁止 stdout），schema 见设计文档 §5.3，理由：不越“接线 + 修复”边界、避免 stdout 污染 | + +CLI 契约：`use_logger = (--log-level is not None) or (--log-file is not None)`；仅 `--log-file` 时控制台级别为 `INFO`。 + +### 1.3 CompilerConfig 字段（`scratchv/compiler.py`） + +| 字段 | 类型 | 默认 | 状态 | +|------|------|------|------| +| `use_logger` | `bool` | `False` | 既有（语义落地） | +| `log_level` | `str` | `"INFO"` | 既有 | +| `log_file` | `str \| None` | `None` | **新增** | +| `log_color` | `bool` | `True` | **新增**（CLI 侧 `sys.stderr.isatty()`） | + +### 1.4 新增内部符号 + +```python +# scratchv/compiler.py +class CompilerDriver: + self._log: logging.Logger | None # 懒加载；关闭日志时保持 None + def _logger(self) -> logging.Logger | None: ... + def _phase(self, name: str, description: str): ... # 返回 log_phase 或 nullcontext() + +class PassManager: + def __init__(self, name: str = "pipeline", + log: logging.Logger | None = None): ... + self._log: logging.Logger | None +``` + +### 1.5 日志名与阶段名常量（实现时逐字使用） + +| 阶段 | `log_phase` name | description 模板 | 触发 | +|------|------------------|------------------|------| +| 解析 | `compiler.parse` | `Parsing {input_path or ''}` | 总是 | +| 优化 | `compiler.optimize` | `Running optimization passes` | `optimize_level != "none"` | +| 代码生成 | `compiler.codegen` | `Generating {backend} code` | 总是 | +| 汇编后处理 | `compiler.asm` | `Running assembly passes` | 总是 | +| 周期估算 | `compiler.cycle` | `Estimating pipeline cycles` | `cycle_stats=True` | +| 写盘 | `compiler.emit` | `Writing {output_path}` | 总是 | + +Pass 明细 logger 名：`get_logger("compiler.passes")`（由 `PassManager` 持有，经 driver 注入）。 +总览 logger 名：`get_logger("compiler")`。 + +### 1.6 配置文件 + +仓库当前**无独立配置文件**，配置载体即 `CompilerConfig` dataclass。若未来引入 TOML，预留节： + +```toml +[logging] +level = "INFO" # <-> log_level +file = "" # <-> log_file +color = true # <-> log_color +# json_log = "" # 保留：<-> --json-log +``` + +--- + +## 二、逐文件改动清单 + +### 2.1 `scratchv/utils/logger.py`（修复，7 处，对应缺陷 D1–D5、D7） + +| # | 锚点（改动前） | 改动 | 关键代码 | +|---|---------------|------|---------| +| F1 | `_ColorFormatter.format` L60-79 | 首行取 `message = super().format(record)`，删除 `record.getMessage()`；返回值改用 `message` | 保留彩色时间/级别/名称拼装 | +| F2 | `_PlainFormatter.format` L85-90 | 同上，`message = super().format(record)` | 文件输出保留异常栈 | +| F3 | 模块级 L97-99 | 新增 `_console_handler: Optional[logging.Handler] = None`、`_file_handler: Optional[logging.Handler] = None` | — | +| F4 | `init_logger` L138 | 在 `_config = {...}` 之前调用 `shutdown()`；末尾记录 `_console_handler` / `_file_handler`；**有 `log_file` 时根 logger 固定 DEBUG（评审 F1）**；FileHandler 打开失败则 `shutdown()` 回滚后抛 `LogFileError` | 先校验 level，再 shutdown，再重建 | +| F5 | `set_level` L198-200 | 删除 `handler.stream == sys.stderr` 扫描，改为 `if _console_handler is not None: _console_handler.setLevel(numeric_level)`；**有文件 handler 时根 logger 保持 DEBUG（评审 F1）**；追加 `_config["level"] = level.upper()` | 文件 handler 恒 DEBUG | +| F6 | `shutdown` L203-209 | 循环内 `removeHandler`，结束后重置 `_root_logger=None`、`_initialized=False`、`_config={}`、两个 handler 引用置 `None`；flush/close 的异常吞掉（流被外部关闭时仍能复位） | 全程可重复调用 | +| F7 | `get_logger` docstring L169-170 | 删除 “Raises: RuntimeError”，改为“未初始化时以默认参数自动初始化” | 文档修正 | +| F8 | 模块级（评审新增） | 新增 `LogFileError(OSError)` 与 `is_initialized() -> bool` | 供 driver/CLI 判定与错误上报 | + +**F4 参考实现**： + +```python +def init_logger(level="INFO", log_file=None, use_color=True) -> None: + global _root_logger, _initialized, _config, _console_handler, _file_handler + + numeric_level = getattr(logging, level.upper(), None) + if not isinstance(numeric_level, int): + raise ValueError(f"Invalid log level: {level}") + + shutdown() # F4：先释放旧资源（幂等） + + _config = {"level": level, "log_file": log_file, "use_color": use_color} + _root_logger = logging.getLogger("scratchv") + # 评审 F1：有文件 handler 时根级别必须放行 DEBUG，控制台级别由 + # console handler 承载，否则 file_handler.setLevel(DEBUG) 形同虚设。 + _root_logger.setLevel(logging.DEBUG if log_file else numeric_level) + + console_handler = logging.StreamHandler(sys.stderr) + console_handler.setLevel(numeric_level) + console_handler.setFormatter(_ColorFormatter(use_color=use_color)) + _root_logger.addHandler(console_handler) + _console_handler = console_handler # F3 + + _file_handler = None + if log_file: + try: + file_handler = logging.FileHandler(log_file, mode="w", encoding="utf-8") + except OSError as exc: # 评审 F4：失败不留半初始化状态 + shutdown() + reason = exc.strerror or str(exc) + raise LogFileError(f"cannot open log file '{log_file}': {reason}") from exc + file_handler.setLevel(logging.DEBUG) + file_handler.setFormatter(_PlainFormatter()) + _root_logger.addHandler(file_handler) + _file_handler = file_handler # F3 + + _initialized = True +``` + +**F6 参考实现**： + +```python +def shutdown() -> None: + global _root_logger, _initialized, _config, _console_handler, _file_handler + if _root_logger is not None: + for handler in list(_root_logger.handlers): + handler.flush() + handler.close() + _root_logger.removeHandler(handler) + _root_logger = None + _initialized = False + _config = {} + _console_handler = None + _file_handler = None +``` + +### 2.2 `scratchv/compiler.py`（接线） + +| # | 锚点（改动前） | 改动 | +|---|---------------|------| +| C1 | 顶部 import（L22-26） | 追加 `from contextlib import nullcontext`、`from scratchv.utils.logger import init_logger, get_logger, log_phase, log_progress, log_step` | +| C2 | `CompilerConfig` L66 之后 | 新增 `log_file: str \| None = None`、`log_color: bool = True` | +| C3 | `PassManager.__init__` L96-98 | 增加 `log: logging.Logger \| None = None` 参数，存 `self._log = log` | +| C4 | `PassManager.run` L113-158 | 循环内 Pass 开始 `log_progress`、完成 `DEBUG`、异常 `ERROR`、提前停止 `WARNING`、结束 `INFO` 汇总（见 §三） | +| C5 | `CompilerDriver.__init__` L219-220 | 追加 `self._log: logging.Logger \| None = None` | +| C6 | `CompilerDriver` 新增方法 | `_logger()` 与 `_phase()`（见 §一 1.4） | +| C7 | `compile()` L236 附近 | 入口按当前 config 初始化：判定改为 `self._log is None or not is_initialized()`（评审 F5）；init 前用 `os.path.realpath` 校验 `log_file` 不与输入/输出路径冲突（评审 F3，冲突抛 `LogFileError`）；`init_logger` + `self._log = get_logger("compiler")` + DEBUG 配置摘要 | +| C8 | `compile()` L244-312 | 6 个阶段用 `with self._phase(...)` 包裹；except 分支追加 `self._log.debug(..., exc_info=True)` **并补 ERROR 摘要**（评审 F2）；成功返回前 INFO `compilation succeeded` | +| C9 | `_parse` L325-346 | 选定解析器后 `DEBUG parser: extended-dsl|dsl|onnx` | +| C10 | `_verify_ir` L350-360 | 末尾 `DEBUG IR verifier: %d issue(s)` | +| C11 | `_run_optimizations` L369 | `PassManager("optimizer", log=self._logger())` | +| C12 | `_generate_riscv_linear` L397-418 | 三步 `log_step("compiler.codegen", ...)`：instruction selection / register allocation (linear-scan\|greedy\|naive) / assembly emission | +| C13 | `_generate_riscv_dag` L420-439 | 五步 `log_step`：DAG build / DAG combine / DAG scheduling / register allocation / assembly emission | +| C14 | `_run_asm_passes` L443-486 | 五个子 pass 的统计日志（见 §三 3.3），`warnings` 行为不变 | + +**C6 参考实现**： + +```python +def _logger(self) -> logging.Logger | None: + if not self.config.use_logger: + return None + if self._log is None: + self._log = get_logger("compiler") + return self._log + +def _phase(self, name: str, description: str): + if not self.config.use_logger: + return nullcontext() + return log_phase(name, description) +``` + +**C7/C8 参考实现（骨架）**： + +```python +def compile(self, input_path, output_path=None, dsl_source=None) -> CompileResult: + errors: list[str] = [] + warnings: list[str] = [] + + if self.config.use_logger and self._log is None: + init_logger(level=self.config.log_level, + log_file=self.config.log_file, + use_color=self.config.log_color) + self._log = get_logger("compiler") + self._log.debug("config: backend=%s optimize=%s reg_alloc=%s", + self.config.backend, self.config.optimize_level, + self.config.reg_alloc) + + if output_path is None: + output_path = "output.ll" if self.config.backend == "llvm" else "output.s" + + # --- 1. Parse --- + try: + with self._phase("compiler.parse", + f"Parsing {input_path or ''}"): + program = self._parse(input_path, dsl_source) + except Exception as e: + if self._log is not None: + self._log.debug("parse exception", exc_info=True) + return CompileResult(success=False, errors=[f"Parse error: {e}"]) + + # ... IR dump 不变 ... + + # --- 2. Verify IR（沿用 use_logger 门控，行为不变）--- + if self.config.use_logger: + self._verify_ir(program, warnings) + + # --- 3. Optimize --- + opt_message = "" + if self.config.optimize_level != "none": + with self._phase("compiler.optimize", "Running optimization passes"): + opt_result = self._run_optimizations(program) + opt_message = opt_result.message + + # ... IR dump 不变 ... + + # --- 4. Code generation --- + try: + with self._phase("compiler.codegen", + f"Generating {self.config.backend} code"): + asm_text = self._generate_code(program) + except Exception as e: + if self._log is not None: + self._log.debug("codegen exception", exc_info=True) + return CompileResult(success=False, + errors=[f"Codegen error: {e}"], ir_dump=ir_dump) + + # --- 5. Post-codegen passes --- + with self._phase("compiler.asm", "Running assembly passes"): + asm_text = self._run_asm_passes(asm_text, warnings) + + # --- 6. Cycle estimation ---（try/except 结构不变） + ... + + # --- 7. Write output --- + with self._phase("compiler.emit", f"Writing {output_path}"): + with open(output_path, "w") as f: + f.write(asm_text) + + if self._log is not None: + for w in warnings: + self._log.warning("%s", w) + self._log.info("compilation succeeded: %s (%d bytes)", + output_path, len(asm_text)) + + return CompileResult(...) +``` + +> 注意：`log_phase` 抛出前已记 `ERROR ... FAILED`；except 内补 `DEBUG` 完整栈与 `ERROR compilation failed: <单行摘要>`（validate 早退、parse/codegen 异常三处均在 return 前记录，评审 F2）。`compile` 骨架其余控制流不变。 + +### 2.3 `scratchv/main.py`（CLI） + +| # | 锚点（改动前） | 改动 | +|---|---------------|------| +| M1 | 顶部 import（L17） | 追加 `from scratchv.utils.logger import shutdown` | +| M2 | `--log-level` L70-74 | 补 `CRITICAL` 到 `choices`；`default` 保持 `None` | +| M3 | L75 之后 | 新增 `--log-file`（`default=None, metavar="FILE"`） | +| M4 | `args_to_config` L145-146 | 改为 4 行映射（见下） | +| M5 | `main()` L238-267 | `try/finally` 包裹**编译段**；`finally` 中 `if config.use_logger: shutdown()`；新增 `except LogFileError` → `error: <原因>`、rc=2（DSL/ONNX 一致，评审 F4）；报告 `print` 在 shutdown 之后 | +| M6 | `main.py:247-266` 报告 print | **不改**（用户可见契约稳定） | + +**M2/M3 参考实现**： + +```python +parser.add_argument( + "--log-level", + choices=["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"], + default=None, + help="Enable structured logging at given level (stderr only)", +) +parser.add_argument( + "--log-file", default=None, metavar="FILE", + help=("Write plain-text DEBUG log to FILE (implies logging at INFO+); " + "must differ from the input/output paths"), +) +``` + +**M4 参考实现**： + +```python +use_logger=args.log_level is not None or args.log_file is not None, +log_level=args.log_level or "INFO", +log_file=args.log_file, +log_color=sys.stderr.isatty(), +``` + +**M5 参考实现**： + +```python +def main(argv: list[str] | None = None) -> int: + parser = build_arg_parser() + args = parser.parse_args(argv) + if args.input is None and args.dsl is None: + parser.print_help() + return 1 + + config = args_to_config(args) + driver = CompilerDriver(config) + try: + result = driver.compile(...) # 原逻辑 + except LogFileError as exc: # 评审 F4：日志文件问题统一 rc=2 + print(f"error: {exc}", file=sys.stderr) + return 2 + except Exception as exc: + if not use_dsl: + raise + print(f"internal compiler error: {exc}", file=sys.stderr) + return 2 + finally: + if config.use_logger: + shutdown() # 编译段结束即 flush/释放 + + # 报告逻辑（纯 print，不依赖 logger；原样不变） + ... +``` + +### 2.4 `tests/test_logger.py`（增补 4 个用例） + +- `test_exc_info_preserved_console_and_file(tmp_path, capsys)` +- `test_reinit_closes_old_handlers(tmp_path)` +- `test_shutdown_resets_state()` +- `test_set_level_updates_console_only(tmp_path)` + +（可用 `import scratchv.utils.logger as logger_mod` 访问 `_initialized/_root_logger/_config/_console_handler/_file_handler`。） + +### 2.5 `tests/test_logger_wiring.py`（新建，13 个用例） + +- `test_args_to_config_logging_fields()` +- `test_log_file_only_implies_logging()` +- `test_invalid_log_level_rejected_by_cli()` +- `test_console_handler_targets_stderr()` +- `test_cli_logging_end_to_end(tmp_path, capsys)` +- `test_no_logging_by_default_keeps_outputs_stable(tmp_path, capsys)` + +评审修复轮补充（F1–F6/F9）： + +- `test_compile_failure_logged(tmp_path, capsys)` — validate 失败路径 ERROR 摘要 +- `test_parse_failure_logged(tmp_path, monkeypatch, capsys)` — parse 失败路径 +- `test_codegen_failure_logged(tmp_path, monkeypatch, capsys)` — codegen 失败路径 +- `test_log_file_same_as_input_refused(tmp_path, capsys)` — 同路径拒绝（输入/输出两种冲突） +- `test_log_file_bad_path_error(tmp_path, capsys)` — 非法路径 rc=2，DSL/ONNX 一致 +- `test_driver_reuse_after_shutdown_keeps_file(tmp_path, capsys)` — shutdown 后按 config 重建 +- `test_pass_exception_logs_traceback(tmp_path, monkeypatch, capsys)` — Pass 异常栈 + +夹具路径： + +```python +DSL = Path(__file__).resolve().parent.parent / "benchmarks" / "cases" / "001_simple_add.dsl" +``` + +### 2.6 明确不改动 + +`scratchv/optimizer/*.py`、`scratchv/backend/*.py`、`scratchv/frontend/*.py`、`scratchv/pass_interface.py`、`scratchv/utils/__init__.py`、`scratchv/standalone/*`、`scratchv/ci/*`、`docs/`（本课题文档除外）、`Makefile`。 + +--- + +## 三、埋点位置清单与消息格式 + +### 3.1 阶段埋点（`compiler.py`，`log_phase`/`log_step`） + +| 位置（符号） | 名称 | 级别 | 消息模板 | +|--------------|------|------|---------| +| `CompilerDriver.compile` 解析 | `compiler.parse` | INFO | `Parsing ...` / `... done (%.3fs)` / `... FAILED (%.3fs)` | +| `.compile` 优化 | `compiler.optimize` | INFO | `Running optimization passes... done (%.3fs)` | +| `._generate_code` 入口 | — | DEBUG | ` -> instruction selection` 等（`log_step`） | +| `._generate_riscv_linear` 三步 | `compiler.codegen` | DEBUG | ` -> register allocation (linear-scan)` | +| `._generate_riscv_dag` 五步 | `compiler.codegen` | DEBUG | ` -> DAG scheduling` | +| `._run_asm_passes` | `compiler.asm` | INFO | 见 3.3 | +| `compile` 周期估算 | `compiler.cycle` | INFO | `Estimating pipeline cycles... done (%.3fs)` | +| `compile` 写盘 | `compiler.emit` | INFO | `Writing ... done (%.3fs)` | +| `compile` 成功返回 | `scratchv.compiler` | INFO | `compilation succeeded: ( bytes)` | +| `compile` 失败返回（validate/parse/codegen） | `scratchv.compiler` | ERROR | `compilation failed: <单行摘要>`（评审 F2） | +| `compile` warnings | `scratchv.compiler` | WARNING | `` | + +### 3.2 Pass 入口埋点（集中在 `PassManager.run`，不改各 pass 文件） + +| Pass 对象 | 定义锚点（不改） | 由谁埋点 | +|-----------|----------------|---------| +| `ConstantFolder.run()` | `scratchv/optimizer/constant_folding.py:21` | `PassManager` | +| `DeadCodeEliminator.run()` | `scratchv/optimizer/dead_code.py:21` | `PassManager` | +| `IRPeepholeOptimizer.run()` | `scratchv/optimizer/peephole.py:22` | `PassManager` | +| `MulAddFusion.run()` | `scratchv/optimizer/muladd_fusion.py:26` | `PassManager` | +| `LICM.run()` | `scratchv/optimizer/licm.py:27` | `PassManager` | +| `InstructionSelector.run()` | `scratchv/backend/instruction_select.py:24` | driver `log_step` | +| `RegisterAllocator.run()` | `scratchv/backend/register_alloc.py:61` | driver `log_step` | +| `LinearScanAllocator.emit()` | `scratchv/backend/regalloc_linear.py:400` | driver `log_step` | +| `AsmEmitter.emit()` | `scratchv/backend/asm_emit.py:88` | driver `log_step` | +| `LLVMCodegen.emit()` | `scratchv/backend/llvm_codegen.py:46` | driver `log_step` | + +`PassManager.run` 循环消息： + +```python +# Pass 开始（INFO，进度） +log_progress(self._log.name, i, total, f"pass {p.name}") +# → "pass constant-folding [1/5] 20.0%"（logger: scratchv.compiler.passes） + +# Pass 完成（DEBUG） +self._log.debug("pass %s: %d change(s) in %.3fs", p.name, result.changes, elapsed) + +# Pass 异常（ERROR，带完整异常栈，评审 F6） +self._log.error("pass '%s' failed: %s", p.name, exc, exc_info=True) + +# 管线提前停止（WARNING） +self._log.warning("pipeline stopped after '%s': %s", p.name, result.message) + +# 全部完成（INFO） +self._log.info("%s: %d pass(es), %d change(s) in %.3fs", + self._name, total, total_changes, sum(timings.values())) +``` + +`log_progress` 仅在 `self._log is not None` 时调用；`PassManager` 默认 `log=None`，既有直接构造 `PassManager()` 的测试零影响。 + +### 3.3 汇编后处理统计（`_run_asm_passes`） + +| 子步骤 | 级别 | 消息模板 | +|--------|------|---------| +| peephole 有变化 / 无变化 | INFO / DEBUG | `asm peephole: %d change(s)` / `asm peephole: no changes` | +| const merge | INFO | `const merge: %d change(s) (%d pairs, %d redundant lui)` | +| scheduler | INFO | `instruction scheduling applied (%d instructions)` | +| beautify | DEBUG | `assembly beautified (%d bytes)` | +| count instr | INFO | `instruction count: %d` | + +### 3.4 `main.py` 埋点 + +`main.py` 本身**不新增日志调用**（仅参数映射与 `shutdown`）；所有日志由 driver 产生，避免与既有 `print` 报告重复。 + +### 3.5 消息格式示例（控制台 / 文件） + +```text +# 控制台（stderr，--log-level DEBUG） +01:16:44 INFO [scratchv.compiler.parse] Parsing a.dsl... done (0.001s) +01:16:44 INFO [scratchv.compiler.passes] pass constant-folding [1/2] 50.0% +01:16:44 DEBUG [scratchv.compiler.passes] pass constant-folding: 2 change(s) in 0.001s +01:16:44 INFO [scratchv.compiler] compilation succeeded: a.s (412 bytes) + +# 文件（--log-file build.log，恒 DEBUG、无颜色） +2026-09-14 01:16:44 INFO [scratchv.compiler.parse] Parsing a.dsl... done (0.001s) +2026-09-14 01:16:44 DEBUG [scratchv.compiler.passes] pass constant-folding: 2 change(s) in 0.001s + +# 异常（console 与 file 均保留栈） +01:16:45 ERROR [scratchv.compiler.parse] Parsing bad.dsl... FAILED (0.000s) +Traceback (most recent call last): + ... +ValueError: boom +``` + +--- + +## 四、实施步骤（顺序执行） + +1. **基线**：`python3 -m pytest tests/test_logger.py -v`（现有 19 用例须全绿，记录基线）。 +2. **修 logger（F1–F7）**：按 §2.1 顺序改；改完立刻跑 `python3 -m pytest tests/test_logger.py -v`。 +3. **补缺陷回归测试**：§2.4 四个用例；`python3 -m pytest tests/test_logger.py -v` 全绿。 +4. **改 compiler（C1–C14）**：先 C1–C7（配置与初始化），再 C8（阶段），再 C9–C14（明细）；每步跑 `python3 -m pytest tests/test_backend.py tests/test_optimizer.py -q` 防回归。 +5. **改 main（M1–M5）**：跑 `python3 -m pytest tests/test_backend.py -q`。 +6. **新增接线测试**：§2.5 六个用例；`python3 -m pytest tests/test_logger_wiring.py -v`。 +7. **全量回归**：`make test`（即 `python3 -m pytest tests/ -v --tb=short`），要求 348+ 用例全绿。 +8. **CLI 冒烟**：设计文档 §4.6 两条命令，人工核对 stdout/stderr/日志文件。 +9. **提交**（由负责人执行）：建议 commit message： + + ```text + feat(logger): wire structured logging into compiler pipeline and fix handler lifecycle + ``` + +--- + +## 五、测试文件清单与用例 + +| 文件 | 用例 | 断言 | 关联 | +|------|------|------|------| +| `tests/test_logger.py` | `test_exc_info_preserved_console_and_file` | stderr 与文件均含 `Traceback ...`、`ValueError: boom`；stderr 无 `\033[` | D1/D2 | +| `tests/test_logger.py` | `test_reinit_closes_old_handlers` | 旧 handler 的 `close` 均被调用（mock spy）；旧 FileHandler `.stream is None`；新 handler 数为 2；根级别 = DEBUG（有文件）、console = INFO | D3/F1 | +| `tests/test_logger.py` | `test_shutdown_resets_state` | `_initialized is False`、`_root_logger is None`、`get_logger` 可自动重启 | D4 | +| `tests/test_logger.py` | `test_set_level_updates_console_only` | console=WARNING、file=DEBUG、根保持 DEBUG、`_config["level"]=="WARNING"`；INFO 不进 stderr 但进文件 | D5/F1 | +| `tests/test_logger.py` | `test_log_file_only_contains_debug` | `level=INFO` + 文件时 DEBUG 行只进文件、不进 stderr | F1 | +| `tests/test_logger.py` | `test_log_file_error_resets_state` | 非法路径抛 `LogFileError` 且 `_initialized/_root_logger/_console_handler/_file_handler` 全部复位 | F4 | +| `tests/test_logger_wiring.py` | `test_args_to_config_logging_fields` | `use_logger/log_level/log_file` 精确映射 | 契约 | +| `tests/test_logger_wiring.py` | `test_log_file_only_implies_logging` | 仅 `--log-file` 时 `use_logger=True, log_level="INFO"` | 契约 | +| `tests/test_logger_wiring.py` | `test_invalid_log_level_rejected_by_cli` | `pytest.raises(SystemExit)` | 契约 | +| `tests/test_logger_wiring.py` | `test_console_handler_targets_stderr` | `logger_mod._console_handler.stream is sys.stderr` | R1/R2 | +| `tests/test_logger_wiring.py` | `test_cli_logging_end_to_end` | rc=0；`out == ""`；stderr 含阶段与 `constant-folding`；日志文件含 DEBUG 与完整时间戳 | D6/R2 | +| `tests/test_logger_wiring.py` | `test_no_logging_by_default_keeps_outputs_stable` | stderr 无 `scratchv.compiler`；stdout 为空；保留原 `OK` 行 | R4 | +| `tests/test_logger_wiring.py` | `test_compile_failure_logged` | validate 失败 rc=1；日志含 `ERROR`/`compilation failed`/`error[E`；stdout 空 | F2 | +| `tests/test_logger_wiring.py` | `test_parse_failure_logged` | parse 异常 rc=1；日志含 `ERROR` 与错误文本 | F2 | +| `tests/test_logger_wiring.py` | `test_codegen_failure_logged` | codegen 异常 rc=1；日志含 `ERROR`/`FAILED` 与错误文本 | F2 | +| `tests/test_logger_wiring.py` | `test_log_file_same_as_input_refused` | rc=2；输入内容不变；stderr 提示 `would overwrite input/output`；无 traceback | F3 | +| `tests/test_logger_wiring.py` | `test_log_file_bad_path_error` | DSL/ONNX 均 rc=2、`cannot open log file`、无 traceback、无半初始化状态 | F4 | +| `tests/test_logger_wiring.py` | `test_driver_reuse_after_shutdown_keeps_file` | `compile→shutdown→compile` 后 `_file_handler` 非空、config 保留、stderr 无 ANSI、文件含成功摘要 | F5 | +| `tests/test_logger_wiring.py` | `test_pass_exception_logs_traceback` | rc=0（E2 语义不变）；日志含 `pass '...' failed` 与完整 `Traceback`/`RuntimeError` | F6 | + +运行命令： + +```bash +python3 -m pytest tests/test_logger.py tests/test_logger_wiring.py -v --tb=short +make test +``` + +注意事项： + +- 本仓 `.venv` 实测为 **Python 3.8.10**（`python3` 解析到 `.venv/bin/python3`）；断言勿依赖 `StreamHandler.close()` 置空 `stream` 的行为（3.8 不置空、3.12 置空），用 `unittest.mock.patch.object(h, "close", wraps=h.close)` 断言更稳。 +- `init_logger` 将 handler 绑定到调用时刻的 `sys.stderr`；在 `capsys` 用例中必须先启用 fixture 再 `init_logger`。 +- 每个用例结束调用 `shutdown()`，避免 handler 跨用例泄漏（可通过 autouse fixture 统一收尾）。 +- 端到端用例使用 `tmp_path` 输出，禁止写仓库工作区。 + +--- + +## 六、验收标准 + +- [ ] `tests/test_logger.py` 25 用例（原 19 + D1–D5/D7 回归 4 + 评审补充 2）全部通过。 +- [ ] `tests/test_logger_wiring.py` 13 用例全部通过。 +- [ ] `make test` 全量 348+ 用例无回归（评审修复轮实测 690 passed / 0 failed）。 +- [ ] `python -m scratchv -o out.s --optimize all --log-level DEBUG --log-file build.log`：stdout 为空；stderr 出现 `scratchv.compiler.parse/optimize/passes/codegen/asm/emit` 日志；`build.log` 含 DEBUG 行与 `YYYY-MM-DD HH:MM:SS` 时间戳。 +- [ ] 不带日志参数运行：stderr 仅原有 `OK RISCV output written to ...`（及 warnings 行），stdout 为空，行为与改动前一致。 +- [ ] `exc_info=True` 的异常栈同时出现在终端与日志文件。 +- [ ] 连续两次 `init_logger` 后旧 handler 全部关闭；`shutdown` 后 `_initialized is False`、`_root_logger is None`。 +- [ ] `grep -rn "StreamHandler(sys.stdout)" scratchv/` 无匹配（人工审查，防止 stdout 污染）。 +- [ ] 变更集仅包含 §2.1–§2.5 所列文件；`optimizer/backend/frontend` 零 diff。 + +--- + +## 七、风险与回退 + +### 7.1 风险表 + +| # | 风险 | 触发条件 | 影响 | 缓解 | +|---|------|---------|------|------| +| R1 | 开启日志时 `_verify_ir` 被联动触发（`compiler.py` 以 `use_logger` 为门控的既有怪癖） | `--log-level` **或 `--log-file`** | stderr 多出 IR warning 行 | 本课题不改门控；显式标注 `--log-file` 同样触发；后续课题把 `verify_ir` 独立为配置字段 | +| R2 | stderr 输出量与格式变化被外部脚本解析 | 显式传日志参数 | 解析脚本受影响 | 默认关闭；仅显式传参激活；报告 `print` 契约不变 | +| R3 | `--log-file` 以 `mode="w"` 截断同名文件 | 复用同一路径 | 旧日志丢失 | 与输入/输出同路径已拒绝（F3，rc=2）；同名旧日志仍会截断，文件名由调用方负责；后续可加 append 选项 | +| R4 | 同进程内多次 `compile()`（多个 driver）反复 init，关闭并截断文件 | 库调用方复用进程 | 日志丢失、句柄抖动 | driver 实例内只 init 一次；`shutdown()` 后复用会按当前 config 重建（F5）；跨实例调用方应自行只 init 一次 | +| R5 | 彩色 ANSI 进入管道/重定向 | stderr 非 TTY | 乱码 | CLI 传 `log_color=sys.stderr.isatty()`；文件恒无颜色 | +| R6 | 日志开销 | 开启 DEBUG + 大模型 | 轻微耗时/大文件 | 关闭时零调用；`%` 惰性格式化；昂贵字段用 `isEnabledFor` 保护 | +| R7 | 敏感信息入日志 | 记录路径/统计 | 低 | 不记录张量内容/权重/源码全文（约束 R8） | +| R8 | 测试间 handler 泄漏导致串扰 | 用例未 `shutdown` | flaky | 每用例收尾 `shutdown()`；autouse fixture | + +### 7.2 回退方案 + +1. **整单回退**：本课题变更集中在 5 个文件，`git revert ` 一步恢复；无数据迁移、无持久化副作用。 +2. **运行时软回退**：`CompilerConfig.use_logger`（默认 `False`）为总开关；CLI 不传 `--log-level/--log-file` 即完全回到旧行为，无需改代码。 +3. **部分回退**：`logger.py` 的 D1–D5、D7 修复独立可用，可保留；若 driver 接线引发问题，可只回退 `compiler.py`/`main.py` 两文件。 +4. **应急开关建议（不实现）**：如需灰度，可加环境变量 `SCRATCHV_LOG_DISABLE=1` 在 `main.py` 强制 `use_logger=False`；本期不引入以控制范围。 + +### 7.3 明确 out-of-scope + +- `--json-log`、`SCRATCHV_LOG_*` 环境变量、`--no-color`、日志轮转（`RotatingFileHandler`）。 +- `scratchv/standalone/*` 工具接入日志、`scratchv/ci/*` 仪表盘接入日志。 +- 各 optimizer/backend pass 文件内部埋点。 +- `main.py` 用户可见 `print` 迁移为 logger。 +- `_verify_ir` 门控修复。 + +### 7.4 为新增模块添加日志（交付物要求的最小指南） + +```python +from scratchv.utils.logger import get_logger + +log = get_logger("optimizer.my_pass") # -> scratchv.optimizer.my_pass +log.debug("my pass start: %d nodes", len(nodes)) # % 惰性格式化 +log.info("my pass: %d change(s)", changes) +with log_phase("my-phase", "Running my pass"): + ... +``` + +规则：级别按语义选（阶段起止 INFO、明细 DEBUG、可恢复 WARNING、失败 ERROR）；只写 stderr/文件；不拼 f-string；单行消息；不记录张量内容。 + +--- + +## 实现结果（2026-09-14 集成） + +> **集成 commit**：`7c4b056`（`feat(topic07): wire compiler logger with defect fixes and phase instrumentation`） +> **集成位置**：`Seven_big_summary` 上第 2 个 topic commit（顺序 06 → **07** → 09 → …） +> **集成后全量**：`PYTHONPATH=. python3.11 -m pytest tests/ -q` → **1011 passed / 13 xfailed / 20 xpassed / 0 failed** +> +> 注：上述 1011 为 `Seven_big_summary` 集成口径；本分支 worktree（基于 main `73c3926`）基线为 681 passed。 + +### 实现文件与要点 + +| 文件 | 要点 | +|------|------| +| `scratchv/utils/logger.py` | D1–D5 / D7 缺陷修复（handler 生命周期与关闭、级别/格式、`shutdown` 复位等）；评审 F1/F4 修复（有文件时根级别 DEBUG、`LogFileError` + 状态回滚、`shutdown` 对流关闭容错、`is_initialized()`） | +| `scratchv/compiler.py` | 阶段埋点：parse / optimize / **passes** / codegen / asm / emit；`use_logger` 接线；评审 F2/F3/F5/F6 修复（失败 ERROR 摘要、日志路径冲突拒绝、shutdown 后重建、Pass 异常栈） | +| `scratchv/main.py` | `--log-level` / `--log-file` 参数与 `args_to_config` 映射；评审 F4：`LogFileError` 统一 rc=2 | +| `tests/test_logger.py` | D1–D5 / D7 回归 + 评审 F1/F4 行为级回归（25 用例） | +| `tests/test_logger_wiring.py` | 接线用例 6 个 + 评审行为级用例 7 个（13 用例） | + +### 测试数字 + +| 口径 | 结果 | +|------|------| +| 定向（`tests/test_logger.py` + `tests/test_logger_wiring.py`，集成时） | 29 passed | +| 分支全量（cherry-pick 前） | 575 passed | +| 集成后全量 | 1011 passed / 13 xfailed / 20 xpassed / 0 failed | +| 评审修复轮定向 | 38 passed | +| 评审修复轮全量（本 worktree） | 690 passed / 0 failed | + +### 与本文档的偏差 / 未完成项 + +- 开发文档 C11 与 §1.5 的 logger 命名存在矛盾，**实现按 §1.5**（使用 `compiler.passes` logger）。 +- `use_logger` 门控 `_verify_ir` 的既有怪癖（§7.1 R1）未动；注意 `--log-file` 也会触发 IR 校验，已在设计 §4.7 与 §7.1 R1 显式标注。 + +### 已知限制 + +- `--log-file` 以 `mode="w"` 截断同名文件（§7.1 R3）；与输入/输出同路径已被拒绝（F3）；同进程多次 compile 的 init/关闭由 driver 负责，`shutdown()` 后复用按当前 config 重建（F5），跨实例复用需调用方自行只 init 一次（R4）。 +- `--json-log`、`SCRATCHV_LOG_*` 环境变量、日志轮转、`scratchv/standalone/*` 与 pass 内部埋点等仍属 out-of-scope（§7.3）。 diff --git "a/docs/topics/07-\347\274\226\350\257\221\345\231\250\346\227\245\345\277\227\345\242\236\345\274\272\345\231\250-\350\256\276\350\256\241\346\226\207\346\241\243.md" "b/docs/topics/07-\347\274\226\350\257\221\345\231\250\346\227\245\345\277\227\345\242\236\345\274\272\345\231\250-\350\256\276\350\256\241\346\226\207\346\241\243.md" new file mode 100644 index 0000000..2f7a1c6 --- /dev/null +++ "b/docs/topics/07-\347\274\226\350\257\221\345\231\250\346\227\245\345\277\227\345\242\236\345\274\272\345\231\250-\350\256\276\350\256\241\346\226\207\346\241\243.md" @@ -0,0 +1,668 @@ +# ScratchV 编译器日志增强器技术设计文档 + +> 文档版本：v1.1 +> 编写日期：2026-09-14 +> 涉及模块：`scratchv/utils/logger.py`（日志基础设施，缺陷修复）、`scratchv/compiler.py`（编译驱动与 PassManager，埋点接线）、`scratchv/main.py`（CLI 参数接线） +> 功能范围：既有结构化日志系统在编译管线中的真实接线；`logger` 已知缺陷修复；`--log-level` / `--log-file` 参数生效；stdout 纯净性保障 +> 修复轮次：2026-09-14 评审 `topic07-review` F1–F8 修订（文件恒 DEBUG 的根级别规则、失败路径记录、日志路径冲突/非法路径防护、shutdown 后复用、Pass 异常栈） + +--- + +## 一、功能介绍 + +### 1.1 功能概述 + +#### 背景现状（2026-09-14 实测） + +课题 7 的源文件 `scratchv/utils/logger.py` 功能已完整实现（`init_logger` / `get_logger` / `set_level` / `log_phase` / `log_progress` / `log_step`），但经全仓检索确认： + +- 除 `scratchv/utils/__init__.py:3` 的导出外，**全仓库零调用**； +- 编译器输出仍全部走 `print(..., file=sys.stderr)`（`scratchv/main.py:247-266`）； +- `--log-level` 在 `scratchv/main.py:70-74` 被解析、`args_to_config` 映射为 `use_logger`（`scratchv/main.py:145-146`），但 `CompilerDriver.compile()` 仅用它门控 IR 校验（`scratchv/compiler.py:257-258`），**日志系统从未被初始化**； +- 课题文档标记为“✅ 已完成”，实际为**功能空转**。 + +同时实测确认以下缺陷： + +| # | 缺陷 | 位置（改动前锚点） | 影响 | +|---|------|------------------|------| +| D1 | `_ColorFormatter.format` 未调用 `super().format(record)` | `logger.py:60-79` | `exc_info=True` / `stack_info` 的异常栈被丢弃（实测 `Traceback in output == False`） | +| D2 | `_PlainFormatter.format` 同样未调用 `super().format` | `logger.py:85-90` | 文件日志同样丢失异常栈 | +| D3 | `init_logger` 重复调用不关闭旧 handler，直接 `handlers.clear()` | `logger.py:138` | 文件描述符泄漏（实测旧 handler `stream` 未置 `None`）、多次初始化叠加文件句柄 | +| D4 | `shutdown` 不重置全局状态 | `logger.py:203-209` | 关闭后 `_initialized` 仍为 `True`、`_root_logger` 仍非空、handler 列表为空 → 后续 `get_logger` 得到“静默 logger” | +| D5 | `set_level` 依赖 `handler.stream == sys.stderr` 识别控制台 handler | `logger.py:198-200` | 在 pytest `capsys`、流包装等场景下匹配失效，级别切换不生效 | +| D6 | `--log-level` 在 `main.py` 解析并映射 `use_logger`，但 driver 从不初始化日志、零埋点 | `main.py:70-74,145-146`；`compiler.py:257` | 课题空转：传参无任何日志输出 | +| D7 | `get_logger` 文档字符串声称未初始化时抛 `RuntimeError` | `logger.py:169-170` | 与“自动初始化”实现不符，误导调用方 | + +> 另有实现怪癖一则（非本课题修复项）：`compiler.py:257` 以 `use_logger` 门控 IR 校验，导致开启日志即触发 IR 校验 warnings，见 §4.7。 + +#### 本课题定义 + +本课题**不重写日志模块**，而是完成两件事： + +1. **接线（wiring）**：让 `CompilerDriver.compile()` 在 `use_logger` 开启时调用 `init_logger`，用 `log_phase` / `log_progress` / `log_step` 对编译管线关键阶段与 Pass 执行埋点；让 `--log-level`、`--log-file` 真正影响运行。 +2. **修复（fix）**：修掉 D1–D7 七个既有缺陷，补齐单元回归测试。 + +#### 明确不做（范围边界） + +- 不修改 `optimizer/*`、`backend/*`、`frontend/*` 等 pass 文件（埋点集中在 `PassManager` 与 driver，见 §四）； +- 不改变 `main.py` 用户可见的 `print` 报告格式（CLI 输出契约保持稳定，结构化日志为**附加**诊断）； +- 本期不引入 `--json-log`（保留命名，见 §2.3.2）； +- 不修复 `_verify_ir` 由 `use_logger` 门控的既有怪癖（记录于 §4.7 风险）。 + +#### 与课题文档的关系 + +`docs/topics/07-编译器日志增强器.md` 描述的是目标形态；本文档描述**从当前 0 调用状态到目标形态的最小落地路径**，并把课题文档中“替换 print”收敛为“先接线、print 契约不动”的保守策略。 + +### 1.2 设计目标 + +- **真实可控**：`--log-level` / `--log-file` 一经传参，终端与文件即出现分级日志；不传参时行为与今日**逐字节等价**。 +- **零污染**：所有日志只写 `sys.stderr` 或显式文件，**永不写 stdout**，保证 `--json`（stdout）等机器可读输出不被污染。 +- **零侵入**：Pass 文件零改动；日志逻辑集中在 driver 与 `PassManager`；关闭日志时该路径零函数调用、零对象构造。 +- **缺陷闭环**：异常栈保留、handler 生命周期正确、状态可重置，均有回归测试。 +- **可测试**：兼容 pytest `capsys` / `tmp_path`，可对 stderr、日志文件做精确断言。 +- **向后兼容**：`logger.py` 公共 API 签名不变；`CompilerConfig` 仅新增默认字段，不改既有字段语义。 + +--- + +## 二、设计规范 + +### 2.1 日志级别规范 + +沿用 Python `logging` 标准级别，级别从低到高： + +| 级别 | 数值 | 颜色（ANSI） | 典型用途 | 本课题实例 | +|------|------|-------------|---------|-----------| +| `DEBUG` | 10 | 灰 `\033[90m` | 详细追踪、每 Pass 结果、代码生成子步骤 | `pass constant-folding: 2 change(s) in 0.001s` | +| `INFO` | 20 | 绿 `\033[32m` | 编译阶段起止、最终成功摘要 | `Parsing a.dsl... done (0.001s)` | +| `WARNING` | 30 | 黄 `\033[33m` | 可恢复问题、管线提前停止 | `pipeline stopped after 'x': ...` | +| `ERROR` | 40 | 红 `\033[31m` | 阶段失败、解析/代码生成错误 | `Generating riscv code... FAILED (0.004s)` | +| `CRITICAL` | 50 | 粗体红 `\033[1;31m` | 致命错误（预留） | 目前无埋点 | + +级别语义约束： + +- **控制台 handler**：级别 = `init_logger(level=...)`，可被 `set_level()` 运行时修改，承载用户可见级别。 +- **文件 handler**：恒为 `DEBUG`，保证日志文件始终是完整记录，不受控制台级别影响。 +- **根 logger**：`logging.getLogger("scratchv")`。**存在文件 handler 时固定 `DEBUG`**（否则 `set_level` 下移控制台级别时会连文件记录一起被根级别过滤掉）；无文件 handler 时级别与 `init_logger(level=...)` 一致。子 logger 继承（`NOTSET`）。 + +### 2.2 输出格式规范 + +#### BNF 表示 + +``` +log_record ::= console_line | file_line +console_line ::= [color_on] timestamp " " level_field " " "[" logger_name "]" " " body [color_off] +file_line ::= full_timestamp " " level_field " " "[" logger_name "]" " " body +timestamp ::= "%H:%M:%S" ; 控制台（locals, record.created） +full_timestamp ::= "%Y-%m-%d %H:%M:%S" ; 文件 +level_field ::= level padded_to_width_8 +logger_name ::= "scratchv" { "." name_part } +body ::= formatted_message [ "\n" traceback ] +formatted_message ::= record.getMessage() ; %-style 惰性格式化后的文本 +color_on/off ::= ANSI 转义序列（见 2.1 表）；文件格式中恒不存在 +``` + +#### 格式细则 + +- 控制台（`_ColorFormatter`）：`dim(时间)` + 空格 + `彩色(级别左对齐8)` + `[粗体(logger名)]` + 消息。 +- 文件（`_PlainFormatter`）：`YYYY-MM-DD HH:MM:SS` + 空格 + `级别左对齐8` + `[logger名]` + 消息；**无 ANSI 码**。 +- 异常栈（修复后）：`body` 由 `super().format(record)` 生成，`exc_info` 存在时自动追加 `Traceback (most recent call last): ...`；`stack_info` 同理。 +- 单条消息应保持单行；多行内容（如 IR dump、汇编）不得整段入日志，只记录摘要/统计。 +- 日志名一律位于 `scratchv.` 命名空间；`get_logger("parser")` 自动得到 `scratchv.parser`。 + +#### 日志命名空间约定（本课题新增部分） + +| 名称 | 来源 | 用途 | +|------|------|------| +| `scratchv.compiler` | `get_logger("compiler")` | driver 总览、配置、结果摘要 | +| `scratchv.compiler.parse` | `log_phase("compiler.parse", ...)` | 解析阶段 | +| `scratchv.compiler.optimize` | `log_phase("compiler.optimize", ...)` | 优化阶段总时长 | +| `scratchv.compiler.passes` | `PassManager` 内部 logger | 逐 Pass 执行明细 | +| `scratchv.compiler.codegen` | `log_phase` / `log_step` | 指令选择、寄存器分配、发射 | +| `scratchv.compiler.asm` | `log_phase("compiler.asm", ...)` | 汇编后处理 | +| `scratchv.compiler.cycle` | `log_phase("compiler.cycle", ...)` | 周期估算 | +| `scratchv.compiler.emit` | `log_phase("compiler.emit", ...)` | 输出写盘 | + +### 2.3 接口契约 + +本节名称与签名即实现契约，开发文档 §一与其逐字一致。 + +#### 2.3.1 Python API（`scratchv.utils.logger`） + +| 符号 | 签名 | 语义 | 异常 | +|------|------|------|------| +| `init_logger` | `(level: str = "INFO", log_file: str \| None = None, use_color: bool = True) -> None` | 初始化/重配置。**幂等**：重复调用先 `shutdown()` 旧 handler 再重建；`log_file` 非空时追加文件 handler（mode=`"w"`，UTF-8，恒 DEBUG），此时根 logger 固定 `DEBUG` | `ValueError`（非法级别）、`LogFileError`（日志文件无法打开；抛出前已 `shutdown()` 清理，无半初始化状态） | +| `get_logger` | `(name: str) -> logging.Logger` | 返回 `scratchv.` 命名空间下 logger；未初始化时自动 `init_logger()`（默认 INFO）；名称已以 `scratchv` 开头则原样保留 | 无 | +| `is_initialized` | `() -> bool` | 返回日志系统当前是否处于已初始化状态；`shutdown()` 后为 `False`。供 driver 判断是否需按当前配置重建（F5） | 无 | +| `set_level` | `(level: str) -> None` | 更新控制台 handler 级别；文件 handler 保持 DEBUG，且存在文件 handler 时根 logger 固定 DEBUG；同步更新 `_config["level"]` | `RuntimeError`（未初始化）、`ValueError`（非法级别） | +| `shutdown` | `() -> None` | flush + close 全部 handler 并移除；**重置** `_root_logger=None`、`_initialized=False`、`_config={}`、处理句柄引用为 `None`。对外部已关闭的流容错（异常吞掉但状态仍复位） | 无（可重复调用） | +| `log_phase` | `(name: str, description: str = "")`（上下文管理器） | 进入 INFO `...`；正常退出 INFO `... done (%.3fs)`；异常退出 ERROR `... FAILED (%.3fs)` 并**原样重抛** | 透传被包裹代码的异常 | +| `log_progress` | `(name: str, current: int, total: int, description: str = "") -> None` | INFO ` [cur/total] pct%`；`total<=0` 时百分比为 0 | 无 | +| `log_step` | `(name: str, step_name: str) -> None` | DEBUG ` -> ` | 无 | + +异常类型：`LogFileError(OSError)` 由 `init_logger`（文件无法打开）与 `CompilerDriver.compile`（日志路径与输入/输出冲突）抛出，CLI 统一捕获并输出 `error: ...`、返回 rc=2。 + +新增模块级私有状态（不属于公共 API，供测试与 `set_level` 使用）： + +```python +_console_handler: Optional[logging.Handler] = None # 新增：控制台 handler 引用 +_file_handler: Optional[logging.Handler] = None # 新增：文件 handler 引用（无文件时为 None） +``` + +#### 2.3.2 CLI 参数（`scratchv.main.build_arg_parser`） + +| 参数 | 类型 / choices | 默认 | 语义 | 状态 | +|------|----------------|------|------|------| +| `--log-level` | `{DEBUG, INFO, WARNING, ERROR, CRITICAL}` | `None` | 开启结构化日志并设定**控制台**级别；`None` = 完全关闭 | 既有；修正为补全 `CRITICAL` 选项 | +| `--log-file` | `FILE`（路径） | `None` | 开启日志并写纯文本文件（文件恒 DEBUG）；与 `--log-level` 同时给出时级别取 `--log-level`；路径与输入或输出文件相同则拒绝（`LogFileError`，rc=2） | **新增** | +| `--json-log` | — | — | **本期不引入**；保留命名 `--json-log FILE`（JSON Lines 写入指定文件，禁止 stdout）。理由：超出“接线 + 修复”边界；`--log-file` 已可离线转换；避免新增 formatter 造成范围膨胀 | 延后（保留） | + +规则： + +- `use_logger = (--log-level 给出) or (--log-file 给出)`；仅给 `--log-file` 时控制台级别默认 `INFO`。 +- CLI 层 `choices` 已拦截非法级别；库调用方传非法级别由 `init_logger` 抛 `ValueError`。 +- 环境变量（`SCRATCHV_LOG_LEVEL`、`SCRATCHV_LOG_FILE`）本期不引入，保留命名。 + +#### 2.3.3 CompilerConfig 字段（`scratchv.compiler.CompilerConfig`） + +| 字段 | 类型 | 默认 | 说明 | 状态 | +|------|------|------|------|------| +| `use_logger` | `bool` | `False` | 日志总开关；`True` 时 `compile()` 调用 `init_logger` 并埋点 | 既有（语义落地） | +| `log_level` | `str` | `"INFO"` | 透传 `init_logger(level=...)` | 既有 | +| `log_file` | `str \| None` | `None` | 透传 `init_logger(log_file=...)` | **新增** | +| `log_color` | `bool` | `True` | 透传 `init_logger(use_color=...)`；CLI 传 `sys.stderr.isatty()` | **新增** | + +新增 `CompilerDriver` 私有辅助（不改公共签名）： + +| 符号 | 签名 | 语义 | +|------|------|------| +| `_logger` | `(self) -> logging.Logger \| None` | `use_logger=False` 返回 `None`；否则懒加载 `get_logger("compiler")`，避免关闭日志时触碰 logging | +| `_phase` | `(self, name: str, description: str)` | `use_logger=False` 返回 `contextlib.nullcontext()`；否则返回 `log_phase(...)` | +| `PassManager.__init__` | `(self, name: str = "pipeline", log: logging.Logger \| None = None)` | 新增可选 `log`；`None` 时 PassManager 不产生任何日志（保持既有测试行为） | + +### 2.4 约束规则 + +- **R1（stderr 唯一出口）**：控制台日志 handler 必须绑定 `sys.stderr`；仓库中禁止新增绑定 `sys.stdout` 的日志 handler。 +- **R2（stdout 纯净）**：`--json` / 未来任何 stdout 机器可读输出，其 stdout 不得因日志开关而改变；日志只能出现在 stderr 或文件。 +- **R3（文件恒 DEBUG 且无颜色）**：文件 handler 级别固定 `DEBUG`，formatter 必须为 `_PlainFormatter`，不得输出 ANSI；存在文件 handler 时根 logger 固定 `DEBUG`，控制台级别由 console handler 承载。 +- **R4（默认关闭）**：不传 `--log-level` / `--log-file` 时不得调用 `get_logger`、不得触发自动初始化、不得新增任何 stderr 输出。 +- **R5（单进程单文件句柄）**：`init_logger` 每次重建 handler 前必须关闭旧 handler；`shutdown` 后必须可再次 `init_logger`。 +- **R6（异常不吞）**：`log_phase` 只负责记录并重抛；任何日志代码不得改变 `compile()` 的控制流与返回值。 +- **R7（惰性格式化）**：日志消息使用 `%` 占位符而非 f-string/即时拼接；昂贵字段仅在 `log.isEnabledFor(...)` 为真时计算。 +- **R8（不泄敏）**：日志只记录路径、级别、计数、耗时、Pass 名；不得记录张量内容、权重或用户源码全文。 +- **R9（单行消息）**：不将多行转储直接作为消息体；需要时记录字符数/指数量级。 + +### 2.5 合法与非法示例 + +**合法示例**： + +```python +from scratchv.utils.logger import init_logger, get_logger, set_level, shutdown + +init_logger(level="debug", log_file="build.log", use_color=False) # 级别大小写不敏感 +init_logger() # 幂等重配置（旧 handler 先关闭） +log = get_logger("parser") # -> scratchv.parser +log = get_logger("scratchv.ir") # -> scratchv.ir（已带前缀，原样保留） +set_level("WARNING") # 控制台 -> WARNING；文件 handler 仍 DEBUG +with log_phase("compiler.parse", "Parsing a.dsl"): + program = parse("a.dsl") +shutdown() # 重置全部状态，可再次 init_logger +``` + +CLI： + +```bash +python -m scratchv a.dsl -o a.s --log-level DEBUG --log-file build.log +python -m scratchv a.dsl -o a.s --log-file build.log # 控制台 INFO，文件 DEBUG +``` + +**非法示例**： + +```python +init_logger(level="VERBOSE") # ✗ ValueError：非法级别 +init_logger(level="INFO", log_file="") # ⚠ 空串按“无文件”处理（文档化行为，不报错） +set_level("TRACE") # ✗ ValueError +set_level("DEBUG") # ✗ 未 init -> RuntimeError +logging.StreamHandler(sys.stdout) # ✗ 违反 R1/R2：污染 --json stdout +get_logger("compiler").info("x") # ⚠ 隐式自动 init（INFO），显式性不足；driver 内禁止 +CompilerConfig(log_level="verbose") # ✗ 运行时 init_logger 抛 ValueError（CLI 已由 choices 拦截） +with log_phase("parse", "x"): # ⚠ 未 init 时隐式自动 init；仅在库用户场景可接受 + ... +``` + +--- + +## 三、测试设计 + +所有新增测试放入 `tests/test_logger.py`（缺陷回归）与 `tests/test_logger_wiring.py`（接线与 CLI）。注意：`init_logger` 会把 handler 绑定到**调用时刻**的 `sys.stderr`，因此使用 `capsys` 的用例必须在 fixture 生效后再 `init_logger`。 + +### 测试用例 1：异常栈保留（D1/D2 回归） + +**文件**：`tests/test_logger.py::test_exc_info_preserved_console_and_file` + +**输入**： + +```python +def test_exc_info_preserved_console_and_file(tmp_path, capsys): + log_path = tmp_path / "exc.log" + init_logger(level="DEBUG", log_file=str(log_path), use_color=False) + try: + raise ValueError("boom") + except ValueError: + get_logger("test.exc").error("caught", exc_info=True) + shutdown() + err = capsys.readouterr().err + file_text = log_path.read_text() +``` + +**预期输出**：`err` 与 `file_text` 均包含 `Traceback (most recent call last)` 且包含 `ValueError: boom`；`err` 中无 ANSI 转义序列（`"\033["` 不在其中）。 + +**验证点**：修复前两者均缺失（已实测）；修复后控制台与文件都保留完整栈；证明 `_ColorFormatter` 与 `_PlainFormatter` 都已改为经 `super().format(record)` 取 body。 + +### 测试用例 2：`init_logger` 幂等与句柄关闭（D3 回归） + +**文件**：`tests/test_logger.py::test_reinit_closes_old_handlers` + +**输入**： + +```python +from unittest import mock + +def test_reinit_closes_old_handlers(tmp_path): + init_logger(level="DEBUG", log_file=str(tmp_path / "a.log")) + old_handlers = list(logging.getLogger("scratchv").handlers) + spies = [mock.patch.object(h, "close", wraps=h.close) for h in old_handlers] + started = [s.start() for s in spies] + init_logger(level="INFO", log_file=str(tmp_path / "b.log")) + for s in spies: + s.stop() + new_handlers = list(logging.getLogger("scratchv").handlers) +``` + +**预期输出**：`started` 中每个 spy 的 `.called` 均为真（旧 handler 全部被 close）；旧 `FileHandler` 的 `.stream is None`；`new_handlers` 长度为 2（控制台 + 文件）；有文件 handler 时根 logger 级别为 `DEBUG`（F1），控制台 handler 级别为 `INFO`。 + +**说明**：本仓 venv 为 Python 3.8.10（实测），`logging.StreamHandler.close()` 不置 `stream=None`（仅 `FileHandler.close()` 置空），故控制台 handler 用 `close` spy 断言，文件 handler 兼用 `.stream is None`；该写法同时兼容 Python 3.12。 + +**验证点**：无 fd 泄漏；重复初始化不会叠加 handler；级别按最后一次调用生效。 + +### 测试用例 3：`shutdown` 状态重置与自动重启（D4 回归） + +**文件**：`tests/test_logger.py::test_shutdown_resets_state` + +**输入**： + +```python +def test_shutdown_resets_state(): + init_logger(level="DEBUG") + shutdown() + assert logger_mod._initialized is False + assert logger_mod._root_logger is None + log = get_logger("after_shutdown") # 自动重新 init + assert isinstance(log, logging.Logger) + shutdown() +``` + +**预期输出**：断言全部通过；`get_logger` 自动重启后不抛异常且能正常记录。 + +**验证点**：`shutdown` 后状态归零；再次使用不会得到“无 handler 静默 logger”。 + +### 测试用例 4：`set_level` 只调控制台、不调文件（D5 回归） + +**文件**：`tests/test_logger.py::test_set_level_updates_console_only` + +**输入**： + +```python +def test_set_level_updates_console_only(tmp_path, capsys): + log_path = tmp_path / "a.log" + init_logger(level="INFO", log_file=str(log_path)) + root = logging.getLogger("scratchv") + assert root.level == logging.DEBUG + set_level("WARNING") + assert logger_mod._console_handler.level == logging.WARNING + assert logger_mod._file_handler.level == logging.DEBUG + assert root.level == logging.DEBUG + log = get_logger("test.setlevel") + log.info("info-suppressed-on-console") # 控制台丢弃，文件保留 + log.warning("warning-shown") + shutdown() +``` + +**预期输出**：全部断言通过（不再依赖 `handler.stream == sys.stderr` 的脆弱比较）；控制台 stderr 无 `info-suppressed-on-console` 而有 `warning-shown`，文件两者都有。 + +**验证点**：运行时级别切换实际生效；文件日志完整记录不变；根 logger 在有文件 handler 时保持 DEBUG；`_config` 同步。 + +### 测试用例 5：CLI 端到端接线（D6 主验证） + +**文件**：`tests/test_logger_wiring.py::test_cli_logging_end_to_end` + +**输入**（`benchmarks/cases/001_simple_add.dsl` 为现成夹具）： + +```python +rc = main([str(dsl), "-o", str(out), "--optimize", "all", + "--log-level", "DEBUG", "--log-file", str(log_file)]) +captured = capsys.readouterr() +``` + +**预期输出**： + +- `rc == 0`；`out` 文件存在且非空； +- `captured.out == ""`（stdout 无任何日志/输出）； +- `captured.err` 包含 `[scratchv.compiler.parse]`、`done (`、`[scratchv.compiler.codegen]`、`[scratchv.compiler.passes]`、`constant-folding`； +- 日志文件包含 `DEBUG` 行与 `YYYY-MM-DD HH:MM:SS` 时间戳，且包含 `pass constant-folding`。 + +**验证点**：`--log-level` / `--log-file` 真正生效；阶段与 Pass 均有日志；stdout 零污染（R2）。 + +### 测试用例 6：默认关闭与 stdout 纯净性 + +**文件**：`tests/test_logger_wiring.py::test_no_logging_by_default_keeps_outputs_stable` + +**输入**： + +```python +rc = main([str(dsl), "-o", str(out)]) # 不带任何日志参数 +captured = capsys.readouterr() +``` + +**预期输出**：`rc == 0`；`"scratchv.compiler" not in captured.err`；`captured.out == ""`；stderr 仍且仅有既有 `OK RISCV output written to ...` 一行。 + +**验证点**：R4 默认零副作用、向后兼容；`--log-level` 缺省不触发 `get_logger`。 + +### 测试用例 7：参数映射与非法级别拦截（补充） + +**文件**：`tests/test_logger_wiring.py::test_args_to_config_logging_fields` + +**输入**： + +```python +args = build_arg_parser().parse_args( + ["input.dsl", "--log-level", "DEBUG", "--log-file", "x.log"]) +config = args_to_config(args) + +with pytest.raises(SystemExit): + build_arg_parser().parse_args(["input.dsl", "--log-level", "VERBOSE"]) +``` + +**预期输出**：`config.use_logger is True`、`config.log_level == "DEBUG"`、`config.log_file == "x.log"`；非法级别被 argparse 以 `SystemExit(2)` 拒绝。 + +**验证点**：CLI → config 契约精确；`log_level` 不再是“解析后丢弃”的孤儿参数。 + +### 测试矩阵小结 + +| 用例 | 缺陷/目标 | 断言对象 | 工具 | +|------|----------|---------|------| +| 1 | D1/D2 | stderr + 文件文本 | `capsys` + `tmp_path` | +| 2 | D3 | handler 生命周期 | 直接检查 handler | +| 3 | D4 | 模块全局状态 | 私有变量断言 | +| 4 | D5 | handler 级别 + `_config` | 私有变量断言 | +| 5 | D6 | CLI 端到端 | `main()` + `capsys` + `tmp_path` | +| 6 | R2/R4 | stdout/stderr 稳定性 | `capsys` | +| 7 | CLI 契约 | config 字段 + argparse | 纯函数 | + +> **评审修复轮补充用例**（2026-09-14，对应 F1–F6/F9）：`test_log_file_only_contains_debug`（文件恒 DEBUG 行为）、`test_log_file_error_resets_state`（非法路径无半初始化状态）、`test_compile_failure_logged` / `test_parse_failure_logged` / `test_codegen_failure_logged`（失败路径 ERROR 收尾）、`test_log_file_same_as_input_refused`（同路径拒绝）、`test_log_file_bad_path_error`（非法路径 rc=2、DSL/ONNX 一致）、`test_driver_reuse_after_shutdown_keeps_file`（shutdown 后按配置重建）、`test_pass_exception_logs_traceback`（Pass 异常栈）。定向文件合计 38 用例。 + +--- + +## 四、修改模块与实现步骤 + +### 4.1 涉及文件 + +| 文件（实际路径） | 抽象角色 | 改动类型 | 是否新建 | +|------------------|---------|---------|---------| +| `scratchv/utils/logger.py` | 日志基础设施 | 修复 D1–D5、D7 | 否 | +| `scratchv/compiler.py` | 编译驱动 / PassManager | 接线、新增两个配置字段与私有辅助 | 否 | +| `scratchv/main.py` | CLI 入口 | 新增 `--log-file`、修正参数映射、退出时 `shutdown` | 否 | +| `tests/test_logger.py` | 缺陷回归测试 | 增补用例 1–4 | 否 | +| `tests/test_logger_wiring.py` | 接线端到端测试 | 新增用例 5–7 | **是** | +| `scratchv/utils/__init__.py` | 导出面 | **不改**（现有 `init_logger`/`get_logger` 导出足够） | 否 | +| `scratchv/optimizer/*.py`、`scratchv/backend/*.py`、`scratchv/frontend/*.py` | 各 pass | **不改**（集中埋点，见 4.3） | 否 | + +> 注：以上路径为 2026-09-14 实测路径，实际路径未来可能因目录重构而不同；若发生重命名，按“日志基础设施 / 编译驱动 / CLI 入口”角色对应即可。 + +### 4.2 修复 `scratchv/utils/logger.py`（D1–D5、D7） + +#### 4.2.1 异常栈保留（D1/D2） + +`_ColorFormatter.format`（`logger.py:60`）与 `_PlainFormatter.format`（`logger.py:85`）首行改为调用 `super().format(record)` 取得 `body`（该调用会填充 `record.message`、`record.exc_text`，处理 `exc_info`/`stack_info`），再拼装前缀： + +```python +# _ColorFormatter.format 伪码（关键差异） +message = super().format(record) # 不再使用 record.getMessage() +... +return f"{time_colored} {level_colored} [{name_colored}] {message}" +``` + +```python +# _PlainFormatter.format 伪码 +message = super().format(record) +return f"{asctime} {record.levelname:<8} [{record.name}] {message}" +``` + +#### 4.2.2 `init_logger` 幂等重建（D3） + +在建立新 handler 前调用 `shutdown()` 关闭并解绑旧 handler；随后记录新 handler 引用： + +```python +shutdown() # 先释放旧资源、重置状态 +_root_logger = logging.getLogger("scratchv") +... +_console_handler = console_handler +_file_handler = file_handler if log_file else None +_initialized = True +``` + +顺序要求：先校验 `level`（保持既有 `ValueError` 行为），再 `shutdown()`，再重建；避免“校验失败却已销毁旧配置”。 + +#### 4.2.3 `shutdown` 状态重置（D4） + +```python +def shutdown() -> None: + global _root_logger, _initialized, _config, _console_handler, _file_handler + if _root_logger is not None: + for handler in list(_root_logger.handlers): + handler.flush() + handler.close() + _root_logger.removeHandler(handler) + _root_logger = None + _initialized = False + _config = {} + _console_handler = None + _file_handler = None +``` + +要求可重复调用（幂等），且不抛异常。 + +#### 4.2.4 `set_level` 句柄引用（D5） + +用 `_console_handler` 引用替代 `handler.stream == sys.stderr` 判断，并同步 `_config["level"]`；文件 handler 保持 `DEBUG` 不动： + +```python +_root_logger.setLevel(numeric_level) +if _console_handler is not None: + _console_handler.setLevel(numeric_level) +_config["level"] = level.upper() +``` + +#### 4.2.5 文档字符串修正（D7） + +删除 `get_logger` 中“Raises: RuntimeError”描述，改为说明“未初始化时以默认参数自动初始化”。 + +### 4.3 接线 `scratchv/compiler.py` + +#### 4.3.1 配置扩展 + +在 `CompilerConfig`（`compiler.py:33-75`）的日志字段区（`log_level` 之后）新增： + +```python +log_file: str | None = None # 日志文件路径；None = 不写文件 +log_color: bool = True # 控制台彩色；CLI 传 sys.stderr.isatty() +``` + +#### 4.3.2 driver 辅助与初始化 + +新增 `_logger()` / `_phase()`（签名见 §2.3.3），并在 `compile()` 入口（`compiler.py:236` 附近）执行**单实例一次**初始化： + +```python +if self.config.use_logger and self._log is None: + init_logger(level=self.config.log_level, + log_file=self.config.log_file, + use_color=self.config.log_color) + self._log = get_logger("compiler") +``` + +随后 `DEBUG` 记录配置摘要（`backend/optimize/reg_alloc`）。成功返回前 `INFO` 记录最终结果（输出路径 + 字节数）；**失败返回前三处均记 `ERROR` 摘要**：validate 早退记录诊断计数 + 首条（单行）、parse/codegen 异常记录错误文本（单行），并保留对应 `DEBUG` 异常栈（`exc_info=True`）。 + +#### 4.3.3 阶段埋点（`log_phase`） + +按现有控制流用 `with self._phase(name, desc):` 包裹（**不改变** try/except 结构与返回路径）： + +| 现有位置（改动前） | 阶段名 | description | 触发条件 | +|------------------|--------|-------------|---------| +| `compiler.py:244-249` 解析 | `compiler.parse` | `Parsing ` | 总是 | +| `compiler.py:257-258` IR 校验 | — | `DEBUG: IR verifier: issue(s)` | `use_logger`（沿用既有门控） | +| `compiler.py:261-264` 优化 | `compiler.optimize` | `Running optimization passes` | `optimize_level != "none"` | +| `compiler.py:281-287` 代码生成 | `compiler.codegen` | `Generating code` | 总是 | +| `compiler.py:290` 汇编后处理 | `compiler.asm` | `Running assembly passes` | 总是 | +| `compiler.py:294-308` 周期估算 | `compiler.cycle` | `Estimating pipeline cycles` | `cycle_stats` | +| `compiler.py:311-312` 写盘 | `compiler.emit` | `Writing ` | 总是 | + +失败路径：validate 早退、解析/代码生成 except 在 `return` 前追加 `ERROR compilation failed: <单行摘要>`，同时保留 `self._log.debug("... exception", exc_info=True)` 供 DEBUG 用户查看完整栈；`log_phase` 的 `FAILED` 行保留。这样默认 INFO 用户与日志文件都能看到失败收尾，而不会只剩空白记录。 + +#### 4.3.4 Pass 级埋点（`PassManager`） + +`PassManager.__init__` 增加可选 `log` 参数（默认 `None`，既有调用零变化）；`run()`（`compiler.py:113-158`）在循环内埋点： + +- 每个 Pass 开始：`log_progress(log.name, i, total, f"pass {p.name}")`（INFO）→ `pass constant-folding [1/5] 20.0%`； +- 每个 Pass 完成：`DEBUG pass : change(s) in s`； +- 异常：`ERROR pass '' failed: `，并带 `exc_info=True` 保留完整异常栈（F6）； +- `result.data is None`：`WARNING pipeline stopped after '': `； +- 全部完成：`INFO : pass(es), change(s) in s`。 + +`_run_optimizations`（`compiler.py:364-382`）创建 PM 时传入 `log=self._logger()`；本文件之外的 pass 源码不动。 + +#### 4.3.5 代码生成子步骤埋点（DEBUG） + +`_generate_riscv_linear`（`compiler.py:397-418`）与 `_generate_riscv_dag`（`compiler.py:420-439`）内用 `log_step("compiler.codegen", ...)` 记录：`instruction selection`、`register allocation (linear-scan|greedy|naive)`、`assembly emission`、`DAG build/combine/scheduling`（DAG 路径）。仅在 `use_logger` 时调用。 + +#### 4.3.6 汇编后处理统计埋点 + +`_run_asm_passes`（`compiler.py:443-486`）已有统计变量，直接转日志： + +| 子 pass | 日志 | +|---------|------| +| peephole（:445-450） | 有变化 INFO `asm peephole: change(s)`；无变化 DEBUG | +| const merge（:452-460） | INFO `const merge: change(s) ( pairs, redundant lui)` | +| scheduler（:462-473） | INFO `instruction scheduling applied ( instructions)` | +| beautify（:475-477） | DEBUG `assembly beautified ( bytes)` | +| count instr（:479-484） | INFO `instruction count: ` | + +与既有 `warnings` 列表并存（warnings 仍返回给 CLI 打印，行为不变）。 + +#### 4.3.7 解析器选择埋点 + +`_parse`（`compiler.py:325-346`）在选定分支后 `DEBUG parser: extended-dsl|dsl|onnx, input=`；`ONNXParser` 失败重试路径记录 `DEBUG` 回退原因。 + +### 4.4 接线 `scratchv/main.py` + +1. **新增参数**（紧随 `--log-level`，`main.py:74` 之后）： + +```python +parser.add_argument("--log-file", default=None, metavar="FILE", + help="Write plain-text DEBUG log to FILE (implies logging at INFO+)") +``` + +2. **`args_to_config` 映射**（`main.py:145-146`）： + +```python +use_logger=args.log_level is not None or args.log_file is not None, +log_level=args.log_level or "INFO", +log_file=args.log_file, +log_color=sys.stderr.isatty(), +``` + +3. **退出收尾**：`main()` 用 `try/finally` 包裹**编译段**，`finally` 中仅当 `config.use_logger` 时调用 `shutdown()`，保证文件 flush 与资源释放；报告段为纯 `print`（不依赖 logger），在 `shutdown()` 之后执行。`LogFileError` 被单独捕获，统一输出 `error: <原因>` 并返回 rc=2（DSL/ONNX 一致），不再落入 `internal compiler error` 或裸 traceback。 + +4. **print 契约不动**：`main.py:247-266` 的用户可见输出保持原样，结构化日志为附加内容（理由：不改变 CLI 输出契约，见 §1.1）。运行 `--log-level` 时 stderr 会先出现日志、后出现原有报告行，顺序由调用点天然保证。 + +### 4.5 stdout 纯净性设计（`--json` 保障） + +- `init_logger` 的控制台 handler 构造即绑定 `sys.stderr`（`logger.py:141`），从机制上保证 stdout 不被日志触碰； +- 规范 R2 禁止任何 stdout handler；`--json-log` 若未来引入，只允许文件目标； +- 回归测试用例 5/6 对 `capsys.readouterr().out == ""` 做硬断言，防止未来回归； +- 其他使用 `--json`（stdout）的 standalone 工具若未来接入 `init_logger`，因上述机制天然安全；本期不修改 standalone 工具。 + +### 4.6 集成与回归测试 + +1. 定向测试：`python3 -m pytest tests/test_logger.py tests/test_logger_wiring.py -v --tb=short` +2. 全量回归：`make test`（`python3 -m pytest tests/ -v --tb=short`，当前 348+ 用例应全绿） +3. CLI 冒烟： + +```bash +python -m scratchv benchmarks/cases/001_simple_add.dsl -o /tmp/a.s \ + --optimize all --log-level DEBUG --log-file /tmp/build.log +# 期望：stdout 为空；stderr 含 scratchv.compiler.* 日志；/tmp/build.log 含 DEBUG 明细 +python -m scratchv benchmarks/cases/001_simple_add.dsl -o /tmp/b.s +# 期望：行为与接线前一致，stderr 仅原有 OK 行 +``` + +4. 发布前人工审查：`grep -rn "StreamHandler(sys.stdout)" scratchv/` 必须无匹配。 + +### 4.7 已知风险与不变式 + +- **`_verify_ir` 门控怪癖**：`compiler.py` 以 `use_logger` 为 IR 校验门控。传 `--log-level` **或本课题新增的 `--log-file`** 都会置 `use_logger=True`，因此两者都会触发 IR 校验并可能新增 `note: IR...` 行；这是既有怪癖的放大面，本课题**不修改**门控本身，仅在此显式标注；后续课题应将 `verify_ir` 独立为配置字段。 +- **日志路径冲突（F3）**：`FileHandler(mode="w")` 会先截断目标文件。`compile()` 在 init 前用 `os.path.realpath` 校验 `log_file` 不等于输入/输出路径，冲突即抛 `LogFileError`（CLI rc=2），输入不被触碰。 +- **重复 init 截断**：文件 handler 为 `mode="w"`，同一进程内多次初始化（含 `shutdown()` 后按当前 config 重建，F5）会截断日志文件；这是既定语义。driver 实例内正常路径只 init 一次；跨 driver／跨实例复用进程的调用方需自行只 init 一次（写入开发文档风险表）。 +- **不变式**：`use_logger=False` 时 `compile()` 不调用任何日志 API，stderr 与今日逐字节一致。 + +--- + +## 五、附录 + +### 5.1 典型控制台输出（`--log-level DEBUG --optimize all`） + +```text +01:16:44 DEBUG [scratchv.compiler] config: backend=riscv optimize=all reg_alloc=greedy +01:16:44 INFO [scratchv.compiler.parse] Parsing benchmarks/cases/001_simple_add.dsl... done (0.001s) +01:16:44 INFO [scratchv.compiler.optimize] Running optimization passes... +01:16:44 INFO [scratchv.compiler.passes] pass constant-folding [1/5] 20.0% +01:16:44 DEBUG [scratchv.compiler.passes] pass constant-folding: 2 change(s) in 0.001s +01:16:44 INFO [scratchv.compiler.passes] pass dead-code-elim [2/5] 40.0% +01:16:44 DEBUG [scratchv.compiler.passes] pass dead-code-elim: 0 change(s) in 0.000s +01:16:44 INFO [scratchv.compiler.optimize] Running optimization passes... done (0.004s) +01:16:44 INFO [scratchv.compiler.codegen] Generating riscv code... done (0.003s) +01:16:44 DEBUG [scratchv.compiler.codegen] -> instruction selection +01:16:44 DEBUG [scratchv.compiler.codegen] -> register allocation (greedy) +01:16:44 DEBUG [scratchv.compiler.codegen] -> assembly emission +01:16:44 INFO [scratchv.compiler.asm] Running assembly passes... done (0.000s) +01:16:44 INFO [scratchv.compiler.emit] Writing output.s... done (0.000s) +01:16:44 INFO [scratchv.compiler] compilation succeeded: output.s (412 bytes) +``` + +（终端中级别名带颜色、时间暗色、logger 名粗体；此处为纯文本还原。） + +### 5.2 日志文件样例（`--log-file build.log`，恒 DEBUG） + +```text +2026-09-14 01:16:44 DEBUG [scratchv.compiler] config: backend=riscv optimize=all reg_alloc=greedy +2026-09-14 01:16:44 INFO [scratchv.compiler.parse] Parsing benchmarks/cases/001_simple_add.dsl... done (0.001s) +2026-09-14 01:16:44 DEBUG [scratchv.compiler.passes] pass constant-folding: 2 change(s) in 0.001s +2026-09-14 01:16:44 INFO [scratchv.compiler] compilation succeeded: output.s (412 bytes) +``` + +### 5.3 保留：`--json-log FILE` 的 JSON Lines 模式（本期不实现） + +若未来引入，单行 schema 约定如下（`--json-log FILE` 只写文件，禁止 stdout）： + +```json +{"ts":"2026-09-14T01:16:44.123","level":"DEBUG","logger":"scratchv.compiler.passes","msg":"pass constant-folding: 2 change(s) in 0.001s"} +{"ts":"2026-09-14T01:16:44.130","level":"ERROR","logger":"scratchv.compiler.parse","msg":"Parse failed: ...","exc":"Traceback (most recent call last):\n..."} +``` + +字段名：`ts`（ISO-8601 本地时间毫秒）、`level`、`logger`、`msg`；`exc` 可选（多行栈以 `\n` 转义）。 + +### 5.4 参考资料 + +- 模板：`/root/Lab/ScratchV/设计文档模板.md` +- 课题：`/root/Lab/ScratchV/docs/topics/07-编译器日志增强器.md` +- 代码：`scratchv/utils/logger.py`、`scratchv/compiler.py`、`scratchv/main.py`、`tests/test_logger.py` +- Python `logging` 官方文档： +- ANSI 转义码： diff --git a/scratchv/compiler.py b/scratchv/compiler.py index fa5459e..1e69ac6 100644 --- a/scratchv/compiler.py +++ b/scratchv/compiler.py @@ -19,11 +19,31 @@ from __future__ import annotations +import logging +import os import time +from contextlib import nullcontext from dataclasses import dataclass, field from typing import Any, Optional from scratchv.pass_interface import CompilerPass, PassResult +from scratchv.utils.logger import ( + LogFileError, + get_logger, + init_logger, + is_initialized, + log_phase, + log_progress, + log_step, +) + + +def _one_line(text: str) -> str: + """Collapse a possibly multi-line error message into one log line (R9).""" + for line in text.splitlines(): + if line.strip(): + return line.strip() + return text # ═══════════════════════════════════════════════════════════════════════════════ @@ -43,7 +63,9 @@ class CompilerConfig: rtol: Relative tolerance for verification. atol: Absolute tolerance for verification. use_logger: Use structured logger instead of print(). - log_level: Log level (DEBUG, INFO, WARNING, ERROR). + log_level: Log level (DEBUG, INFO, WARNING, ERROR, CRITICAL). + log_file: Optional plain-text log file (always DEBUG level). + log_color: Enable ANSI colors on the console handler. use_dag_isel: Use DAG-based instruction selection. beautify_asm: Run assembly beautifier on output. peephole_asm: Run assembly-level peephole optimiser. @@ -64,6 +86,8 @@ class CompilerConfig: atol: float = 1e-8 use_logger: bool = False log_level: str = "INFO" + log_file: str | None = None + log_color: bool = True use_dag_isel: bool = False beautify_asm: bool = False peephole_asm: bool = False @@ -93,9 +117,11 @@ class PassManager: result = pm.run(program) """ - def __init__(self, name: str = "pipeline"): + def __init__(self, name: str = "pipeline", + log: logging.Logger | None = None): self._name = name self._passes: list[CompilerPass] = [] + self._log = log @property def name(self) -> str: @@ -121,12 +147,18 @@ def run(self, input_data: Any) -> PassResult: messages: list[str] = [] all_warnings: list[str] = [] timings: dict[str, float] = {} + total = len(self._passes) - for p in self._passes: + for i, p in enumerate(self._passes, 1): + if self._log is not None: + log_progress(self._log.name, i, total, f"pass {p.name}") t0 = time.perf_counter() try: result = p.run(data) except Exception as exc: + if self._log is not None: + self._log.error("pass '%s' failed: %s", p.name, exc, + exc_info=True) return PassResult( data=None, changes=total_changes, @@ -135,8 +167,14 @@ def run(self, input_data: Any) -> PassResult: ) elapsed = time.perf_counter() - t0 timings[p.name] = elapsed + if self._log is not None: + self._log.debug("pass %s: %d change(s) in %.3fs", + p.name, result.changes, elapsed) if result.data is None: + if self._log is not None: + self._log.warning("pipeline stopped after '%s': %s", + p.name, result.message) return PassResult( data=None, changes=total_changes, @@ -150,6 +188,11 @@ def run(self, input_data: Any) -> PassResult: messages.append(f"[{p.name}] {result.message}") all_warnings.extend(result.warnings) + if self._log is not None: + elapsed_total = sum(timings.values()) + self._log.info("%s: %d pass(es), %d change(s) in %.3fs", + self._name, total, total_changes, elapsed_total) + return PassResult( data=data, changes=total_changes, @@ -221,6 +264,29 @@ class CompilerDriver: def __init__(self, config: CompilerConfig | None = None): self.config = config or CompilerConfig() + self._log: logging.Logger | None = None + + # ── Internal: logging helpers ─────────────────────────────────────────── + + def _logger(self) -> logging.Logger | None: + """Return the driver logger, or ``None`` when logging is disabled.""" + if not self.config.use_logger: + return None + if self._log is None: + self._log = get_logger("compiler") + return self._log + + def _pass_logger(self) -> logging.Logger | None: + """Return the per-pass detail logger (``scratchv.compiler.passes``).""" + if self._logger() is None: + return None + return get_logger("compiler.passes") + + def _phase(self, name: str, description: str): + """Return a ``log_phase`` context or a no-op when logging is off.""" + if not self.config.use_logger: + return nullcontext() + return log_phase(name, description) # ── Public API ────────────────────────────────────────────────────────── @@ -239,10 +305,37 @@ def compile(self, input_path: str, output_path: str | None = None, errors: list[str] = [] warnings: list[str] = [] - # Resolve output path + # Resolve output path first so the log file can be validated against + # both the input and the output path. if output_path is None: output_path = "output.ll" if self.config.backend == "llvm" else "output.s" + # Refuse a log file that would clobber the input or output file: + # the FileHandler opens with mode="w" before parsing would run (F3). + if self.config.use_logger and self.config.log_file: + log_real = os.path.realpath(self.config.log_file) + for role, path in (("input", input_path), ("output", output_path)): + if path and os.path.realpath(path) == log_real: + raise LogFileError( + f"log file '{self.config.log_file}' would overwrite " + f"{role} file '{path}'" + ) + + # Initialise structured logging once per driver instance; rebuild it + # if a previous shutdown() released the handlers so the configured + # level/file/color are honoured instead of silently reverting to + # defaults (F5). + if self.config.use_logger and ( + self._log is None or not is_initialized() + ): + init_logger(level=self.config.log_level, + log_file=self.config.log_file, + use_color=self.config.log_color) + self._log = get_logger("compiler") + self._log.debug("config: backend=%s optimize=%s reg_alloc=%s", + self.config.backend, self.config.optimize_level, + self.config.reg_alloc) + use_dsl = ( dsl_source is not None or (input_path and input_path.endswith(".dsl")) @@ -260,6 +353,12 @@ def compile(self, input_path: str, output_path: str | None = None, ) if collector.has_errors: diagnostics = collector.errors + if self._log is not None: + first = _one_line(str(diagnostics[0])) if diagnostics else "" + self._log.error( + "compilation failed: %d error(s); first: %s", + len(diagnostics), first, + ) return CompileResult( success=False, errors=[str(error) for error in diagnostics], @@ -270,8 +369,15 @@ def compile(self, input_path: str, output_path: str | None = None, # --- 1. Parse --- try: - program = self._parse(input_path, dsl_source) + with self._phase( + "compiler.parse", + f"Parsing {input_path or ''}", + ): + program = self._parse(input_path, dsl_source) except Exception as e: + if self._log is not None: + self._log.debug("parse exception", exc_info=True) + self._log.error("compilation failed: %s", _one_line(str(e))) if use_dsl: from scratchv.frontend.dsl_errors import DSLSyntaxError if isinstance(e, DSLSyntaxError): @@ -297,8 +403,17 @@ def compile(self, input_path: str, output_path: str | None = None, # --- 3. Optimize --- opt_message = "" if self.config.optimize_level != "none": - opt_result = self._run_optimizations(program) + with self._phase("compiler.optimize", "Running optimization passes"): + opt_result = self._run_optimizations(program) opt_message = opt_result.message + if opt_result.data is None and self._log is not None: + # A pass failed or stopped the pipeline (E2: control flow is + # unchanged), so flag that codegen continues on partially + # optimized IR instead of letting "succeeded" mislead. + self._log.warning( + "optimization did not complete; continuing with " + "partially optimized IR: %s", opt_result.message, + ) ir_dump_after = "" if self.config.dump_ir: @@ -316,37 +431,53 @@ def compile(self, input_path: str, output_path: str | None = None, # --- 4. Code generation --- try: - asm_text = self._generate_code(program) + with self._phase( + "compiler.codegen", + f"Generating {self.config.backend} code", + ): + asm_text = self._generate_code(program) except Exception as e: + if self._log is not None: + self._log.debug("codegen exception", exc_info=True) + self._log.error("compilation failed: %s", _one_line(str(e))) return CompileResult( success=False, errors=[f"Codegen error: {e}"], ir_dump=ir_dump, ) # --- 5. Post-codegen passes --- - asm_text = self._run_asm_passes(asm_text, warnings) + with self._phase("compiler.asm", "Running assembly passes"): + asm_text = self._run_asm_passes(asm_text, warnings) # --- 6. Cycle estimation --- cycle_report = "" if self.config.cycle_stats: - from scratchv.backend.cycle_estimator import ( - PipelineCycleEstimator, PipelineConfig, - ) - pconfig = PipelineConfig( - enable_forwarding=self.config.enable_forwarding, - branch_predictor=self.config.branch_predictor, - ) - estimator = PipelineCycleEstimator(pconfig) - try: - cstats = estimator.estimate(asm_text) - cycle_report = estimator.report(cstats) - warnings.append(estimator.report_short(cstats)) - except Exception as e: - warnings.append(f"Cycle estimation failed: {e}") + with self._phase("compiler.cycle", "Estimating pipeline cycles"): + from scratchv.backend.cycle_estimator import ( + PipelineCycleEstimator, PipelineConfig, + ) + pconfig = PipelineConfig( + enable_forwarding=self.config.enable_forwarding, + branch_predictor=self.config.branch_predictor, + ) + estimator = PipelineCycleEstimator(pconfig) + try: + cstats = estimator.estimate(asm_text) + cycle_report = estimator.report(cstats) + warnings.append(estimator.report_short(cstats)) + except Exception as e: + warnings.append(f"Cycle estimation failed: {e}") # --- 7. Write output --- - with open(output_path, "w") as f: - f.write(asm_text) + with self._phase("compiler.emit", f"Writing {output_path}"): + with open(output_path, "w") as f: + f.write(asm_text) + + if self._log is not None: + for w in warnings: + self._log.warning("%s", w) + self._log.info("compilation succeeded: %s (%d bytes)", + output_path, len(asm_text)) return CompileResult( success=True, @@ -372,12 +503,19 @@ def _parse(self, input_path: str, dsl_source: str | None = None): with open(input_path) as f: source = f.read() from scratchv.frontend.dsl_extended import ExtendedDSLParser - return ExtendedDSLParser().parse( + program = ExtendedDSLParser().parse( source or "", filename=input_path or "", ) + if self._log is not None: + self._log.debug("parser: extended-dsl, input=%s", + input_path or "") + return program else: from scratchv.frontend.onnx_parser import ONNXParser - return ONNXParser().parse(input_path) + program = ONNXParser().parse(input_path) + if self._log is not None: + self._log.debug("parser: onnx, input=%s", input_path) + return program # ── Internal: verify IR ───────────────────────────────────────────────── @@ -392,6 +530,8 @@ def _verify_ir(self, program, warnings: list[str]) -> None: warnings.append(f"IR: {msg}") else: warnings.append(f"IR(warning): {msg}") + if self._log is not None: + self._log.debug("IR verifier: %d issue(s)", len(issues)) # ── Internal: optimizations ───────────────────────────────────────────── @@ -400,7 +540,7 @@ def _run_optimizations(self, program) -> PassResult: from scratchv.optimizer.constant_folding import ConstantFolder from scratchv.optimizer.dead_code import DeadCodeEliminator - pm = PassManager("optimizer") + pm = PassManager("optimizer", log=self._pass_logger()) pm.add(_PassAdapter("constant-folding", ConstantFolder(program))) pm.add(_PassAdapter("dead-code-elim", DeadCodeEliminator(program))) @@ -434,20 +574,32 @@ def _generate_riscv_linear(self, program) -> str: from scratchv.backend.register_alloc import RegisterAllocator from scratchv.backend.asm_emit import AsmEmitter + if self._log is not None: + log_step("compiler.codegen", "instruction selection") selector = InstructionSelector(program) machine_instrs = selector.run() # Linear-scan: skip greedy allocator, use liveness-driven allocator if self.config.reg_alloc == "linear": + if self._log is not None: + log_step("compiler.codegen", + "register allocation (linear-scan)") from scratchv.backend.regalloc_linear import ( LinearScanAllocator, block_from_machine_instrs, ) ls_insts = block_from_machine_instrs(machine_instrs) lsa = LinearScanAllocator() + if self._log is not None: + log_step("compiler.codegen", "assembly emission") return lsa.emit(ls_insts) + if self._log is not None: + log_step("compiler.codegen", + f"register allocation ({self.config.reg_alloc})") alloc = RegisterAllocator(machine_instrs, mode=self.config.reg_alloc) allocated = alloc.run() + if self._log is not None: + log_step("compiler.codegen", "assembly emission") emitter = AsmEmitter(allocated) return emitter.emit() @@ -457,18 +609,29 @@ def _generate_riscv_dag(self, program) -> str: from scratchv.backend.register_alloc import RegisterAllocator from scratchv.backend.asm_emit import AsmEmitter + if self._log is not None: + log_step("compiler.codegen", "DAG build") builder = DAGBuilder(program) dag = builder.run() + if self._log is not None: + log_step("compiler.codegen", "DAG combine") combiner = DAGCombiner(dag) combiner.run() + if self._log is not None: + log_step("compiler.codegen", "DAG scheduling") scheduler = DAGScheduler(dag) machine_instrs = scheduler.run() + if self._log is not None: + log_step("compiler.codegen", + f"register allocation ({self.config.reg_alloc})") alloc = RegisterAllocator(machine_instrs, mode=self.config.reg_alloc) allocated = alloc.run() + if self._log is not None: + log_step("compiler.codegen", "assembly emission") emitter = AsmEmitter(allocated) return emitter.emit() @@ -482,6 +645,11 @@ def _run_asm_passes(self, asm_text: str, warnings: list[str]) -> str: asm_text, changes = opt.optimize(asm_text) if changes: warnings.append(f"Asm peephole: {changes} changes") + if self._log is not None: + if changes: + self._log.info("asm peephole: %d change(s)", changes) + else: + self._log.debug("asm peephole: no changes") if self.config.const_merge: from scratchv.backend.const_merge import merge_constants_detailed @@ -492,6 +660,12 @@ def _run_asm_passes(self, asm_text: str, warnings: list[str]) -> str: f"({stats.merged_pairs} pairs, " f"{stats.redundant_lui_removed} redundant lui)" ) + if self._log is not None: + self._log.info( + "const merge: %d change(s) (%d pairs, %d redundant lui)", + stats.total_changes, stats.merged_pairs, + stats.redundant_lui_removed, + ) if self.config.schedule: from scratchv.backend.inst_scheduler import ( @@ -505,10 +679,18 @@ def _run_asm_passes(self, asm_text: str, warnings: list[str]) -> str: f" {inst.opcode} " + ", ".join(inst.operands) for inst in scheduled ) + if self._log is not None: + self._log.info( + "instruction scheduling applied (%d instructions)", + len(scheduled), + ) if self.config.beautify_asm: from scratchv.backend.asm_beautifier import beautify_asm asm_text = beautify_asm(asm_text) + if self._log is not None: + self._log.debug("assembly beautified (%d bytes)", + len(asm_text)) if self.config.count_instr: from scratchv.backend.inst_counter import count_instructions @@ -516,6 +698,8 @@ def _run_asm_passes(self, asm_text: str, warnings: list[str]) -> str: total = sum(v for k, v in counts.items() if not k.startswith("_") and isinstance(v, int)) warnings.append(f"Instruction count: {total}") + if self._log is not None: + self._log.info("instruction count: %d", total) return asm_text diff --git a/scratchv/main.py b/scratchv/main.py index 52feff5..ca7ecea 100644 --- a/scratchv/main.py +++ b/scratchv/main.py @@ -15,6 +15,7 @@ import sys from scratchv.compiler import CompilerConfig, CompilerDriver, CompileResult +from scratchv.utils.logger import LogFileError, shutdown # ═══════════════════════════════════════════════════════════════════════════════ @@ -68,9 +69,15 @@ def build_arg_parser() -> argparse.ArgumentParser: # ── Topic module flags ────────────────────────────────────────────── parser.add_argument( - "--log-level", choices=["DEBUG", "INFO", "WARNING", "ERROR"], + "--log-level", + choices=["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"], default=None, - help="Enable structured logging at given level", + help="Enable structured logging at given level (stderr only)", + ) + parser.add_argument( + "--log-file", default=None, metavar="FILE", + help=("Write plain-text DEBUG log to FILE (implies logging at INFO+); " + "must differ from the input/output paths"), ) parser.add_argument( "--verify-ir", action="store_true", @@ -142,8 +149,10 @@ def args_to_config(args: argparse.Namespace) -> CompilerConfig: verify=args.verify, rtol=args.rtol, atol=args.atol, - use_logger=args.log_level is not None, + use_logger=args.log_level is not None or args.log_file is not None, log_level=args.log_level or "INFO", + log_file=args.log_file, + log_color=sys.stderr.isatty(), use_dag_isel=args.dag_isel, beautify_asm=args.beautify, peephole_asm=args.peephole_asm, @@ -245,11 +254,19 @@ def main(argv: list[str] | None = None) -> int: output_path=args.output, dsl_source=args.dsl if hasattr(args, 'dsl') else None, ) + except LogFileError as exc: + # User-facing log-file problem: report it the same way for DSL and + # ONNX inputs instead of a misleading internal error/traceback. + print(f"error: {exc}", file=sys.stderr) + return 2 except Exception as exc: if not use_dsl: raise print(f"internal compiler error: {exc}", file=sys.stderr) return 2 + finally: + if config.use_logger: + shutdown() # Report if result.ir_dump: diff --git a/scratchv/utils/logger.py b/scratchv/utils/logger.py index fc061bd..1d0981a 100644 --- a/scratchv/utils/logger.py +++ b/scratchv/utils/logger.py @@ -64,7 +64,9 @@ def format(self, record: logging.LogRecord) -> str: "%H:%M:%S", time.localtime(record.created), ) name = record.name - message = record.getMessage() + # Delegate to the base formatter so exc_info / stack_info are + # rendered into the message body (D1). + message = super().format(record) if self.use_color and levelname in _COLORS: color = _COLORS[levelname] @@ -86,8 +88,11 @@ def format(self, record: logging.LogRecord) -> str: asctime = time.strftime( "%Y-%m-%d %H:%M:%S", time.localtime(record.created), ) + # Delegate to the base formatter so exc_info / stack_info are + # rendered into the message body (D2). + message = super().format(record) return (f"{asctime} {record.levelname:<8} " - f"[{record.name}] {record.getMessage()}") + f"[{record.name}] {message}") # --------------------------------------------------------------------------- @@ -97,6 +102,16 @@ def format(self, record: logging.LogRecord) -> str: _root_logger: Optional[logging.Logger] = None _initialized: bool = False _config: dict = {} +_console_handler: Optional[logging.Handler] = None +_file_handler: Optional[logging.Handler] = None + + +class LogFileError(OSError): + """Raised when the configured log file cannot be opened or is unsafe. + + Subclasses :class:`OSError` so callers that already guard file I/O + keep working; the CLI reports it as a user-facing error (exit code 2). + """ def init_logger( @@ -111,46 +126,67 @@ def init_logger( Args: level: Log level string (DEBUG, INFO, WARNING, ERROR, CRITICAL). + Applies to the console handler. When ``log_file`` is given the + root logger is pinned to DEBUG so the file stays a complete + record. log_file: Optional path to write log output to (plain text, no color). use_color: Enable ANSI color output on console. Raises: ValueError: If level is not a valid log level string. + LogFileError: If the log file cannot be opened. Any partially + initialized state is torn down before the error propagates. """ - global _root_logger, _initialized, _config + global _root_logger, _initialized, _config, _console_handler, _file_handler # Validate level numeric_level = getattr(logging, level.upper(), None) if not isinstance(numeric_level, int): raise ValueError(f"Invalid log level: {level}") + # Release previous handlers before rebuilding (D3). Validating the + # level first ensures a failed re-init does not destroy prior config. + shutdown() + _config = { "level": level, "log_file": log_file, "use_color": use_color, } - # Configure root logger + # Configure root logger. With a file handler the root must let DEBUG + # records through, otherwise the handler-level DEBUG would be filtered + # out before reaching the file (F1); the console handler still carries + # the user-visible level. _root_logger = logging.getLogger("scratchv") - _root_logger.setLevel(numeric_level) - - # Remove any existing handlers - _root_logger.handlers.clear() + _root_logger.setLevel(logging.DEBUG if log_file else numeric_level) # Console handler console_handler = logging.StreamHandler(sys.stderr) console_handler.setLevel(numeric_level) console_handler.setFormatter(_ColorFormatter(use_color=use_color)) _root_logger.addHandler(console_handler) + _console_handler = console_handler # File handler + _file_handler = None if log_file: - file_handler = logging.FileHandler( - log_file, mode="w", encoding="utf-8", - ) + try: + file_handler = logging.FileHandler( + log_file, mode="w", encoding="utf-8", + ) + except OSError as exc: + # Roll back the half-built logger: close the console handler and + # reset global state so callers never observe a broken logger. + shutdown() + reason = exc.strerror or str(exc) + raise LogFileError( + f"cannot open log file '{log_file}': {reason}" + ) from exc file_handler.setLevel(logging.DEBUG) # Always write DEBUG to file file_handler.setFormatter(_PlainFormatter()) _root_logger.addHandler(file_handler) + _file_handler = file_handler _initialized = True @@ -159,15 +195,14 @@ def get_logger(name: str) -> logging.Logger: """Get or create a named logger under the scratchv namespace. If no name prefix is given, 'scratchv.' is prepended automatically. + When the logging system has not been initialised, it is initialised + automatically with default parameters. Args: name: Logger name (e.g., 'parser', 'optimizer.constant_folding'). Returns: A logging.Logger instance. - - Raises: - RuntimeError: If init_logger() has not been called. """ if not _initialized: # Auto-initialize with defaults @@ -178,8 +213,21 @@ def get_logger(name: str) -> logging.Logger: return logging.getLogger(name) +def is_initialized() -> bool: + """Return whether ``init_logger()`` is currently active. + + ``False`` after ``shutdown()``; callers can use this to decide whether + the logging system must be rebuilt with their configuration. + """ + return _initialized + + def set_level(level: str) -> None: - """Change the log level of the root scratchv logger at runtime. + """Change the console log level of the root scratchv logger at runtime. + + The file handler always stays at DEBUG, and while a file handler is + attached the root logger stays at DEBUG as well so records reach the + file; the runtime level is enforced by the console handler (F1). Args: level: New log level string. @@ -194,19 +242,39 @@ def set_level(level: str) -> None: numeric_level = getattr(logging, level.upper(), None) if not isinstance(numeric_level, int): raise ValueError(f"Invalid log level: {level}") - _root_logger.setLevel(numeric_level) - for handler in _root_logger.handlers: - if hasattr(handler, "stream") and handler.stream == sys.stderr: - handler.setLevel(numeric_level) + if _file_handler is not None: + _root_logger.setLevel(logging.DEBUG) + else: + _root_logger.setLevel(numeric_level) + # Update the console handler only; the file handler always stays at + # DEBUG so the log file remains a complete record (D5). + if _console_handler is not None: + _console_handler.setLevel(numeric_level) + _config["level"] = level.upper() def shutdown() -> None: - """Flush and close all logging handlers.""" + """Flush and close all logging handlers and reset global state. + + Safe to call repeatedly, and robust against streams that were already + closed externally (e.g. pytest capture teardown): failures are + swallowed so the state reset below always runs. After shutdown the + logging system can be re-initialised with ``init_logger()``. + """ + global _root_logger, _initialized, _config, _console_handler, _file_handler if _root_logger is not None: - for handler in _root_logger.handlers: - handler.flush() - handler.close() - _root_logger.handlers.clear() + for handler in list(_root_logger.handlers): + try: + handler.flush() + handler.close() + except Exception: + pass + _root_logger.removeHandler(handler) + _root_logger = None + _initialized = False + _config = {} + _console_handler = None + _file_handler = None # --------------------------------------------------------------------------- diff --git a/tests/test_logger.py b/tests/test_logger.py index 469aab0..545aac5 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -3,8 +3,10 @@ import logging import os import tempfile +from unittest import mock import pytest +import scratchv.utils.logger as logger_mod from scratchv.utils.logger import ( init_logger, get_logger, @@ -182,3 +184,124 @@ def test_phase_failure(self): except RuntimeError: pass # expected shutdown() + + +class TestLoggerDefectRegressions: + """Regression tests for the known logger defects D1-D5.""" + + def teardown_method(self): + shutdown() + + def test_exc_info_preserved_console_and_file(self, tmp_path, capsys): + log_path = tmp_path / "exc.log" + init_logger(level="DEBUG", log_file=str(log_path), use_color=False) + try: + raise ValueError("boom") + except ValueError: + get_logger("test.exc").error("caught", exc_info=True) + shutdown() + + err = capsys.readouterr().err + file_text = log_path.read_text() + + assert "Traceback (most recent call last)" in err + assert "ValueError: boom" in err + assert "Traceback (most recent call last)" in file_text + assert "ValueError: boom" in file_text + assert "\033[" not in err + + def test_reinit_closes_old_handlers(self, tmp_path): + init_logger(level="DEBUG", log_file=str(tmp_path / "a.log")) + old_handlers = list(logging.getLogger("scratchv").handlers) + spies = [ + mock.patch.object(h, "close", wraps=h.close) + for h in old_handlers + ] + started = [s.start() for s in spies] + try: + init_logger(level="INFO", log_file=str(tmp_path / "b.log")) + finally: + for s in spies: + s.stop() + + assert all(m.called for m in started) + old_file = next( + h for h in old_handlers + if isinstance(h, logging.FileHandler) + ) + assert old_file.stream is None + new_handlers = list(logging.getLogger("scratchv").handlers) + assert len(new_handlers) == 2 + # With a file handler the root logger stays at DEBUG so the file + # receives DEBUG records; the console handler carries the level (F1). + assert logging.getLogger("scratchv").level == logging.DEBUG + assert logger_mod._console_handler.level == logging.INFO + + def test_shutdown_resets_state(self): + init_logger(level="DEBUG") + shutdown() + assert logger_mod._initialized is False + assert logger_mod._root_logger is None + assert logger_mod._console_handler is None + assert logger_mod._file_handler is None + assert logger_mod._config == {} + + log = get_logger("after_shutdown") + assert isinstance(log, logging.Logger) + log.info("revived logger") + shutdown() + + def test_set_level_updates_console_only(self, tmp_path, capsys): + log_path = tmp_path / "a.log" + init_logger(level="INFO", log_file=str(log_path)) + root = logging.getLogger("scratchv") + assert root.level == logging.DEBUG + + set_level("WARNING") + assert logger_mod._console_handler.level == logging.WARNING + assert logger_mod._file_handler.level == logging.DEBUG + assert root.level == logging.DEBUG + assert logger_mod._config["level"] == "WARNING" + + # Verify actual routing, not just handler levels: INFO is dropped on + # the console but still recorded in the file. + log = get_logger("test.setlevel") + log.info("info-suppressed-on-console") + log.warning("warning-shown") + shutdown() + + err = capsys.readouterr().err + text = log_path.read_text() + assert "info-suppressed-on-console" not in err + assert "warning-shown" in err + assert "info-suppressed-on-console" in text + assert "warning-shown" in text + + def test_log_file_only_contains_debug(self, tmp_path, capsys): + log_path = tmp_path / "debug.log" + init_logger(level="INFO", log_file=str(log_path), use_color=False) + log = get_logger("test.debug_file") + log.debug("debug-only-line") + log.info("info-line") + shutdown() + + err = capsys.readouterr().err + text = log_path.read_text() + + assert "debug-only-line" in text + assert "info-line" in text + assert "debug-only-line" not in err + assert "info-line" in err + + def test_log_file_error_resets_state(self, tmp_path, capsys): + bad_path = tmp_path / "missing_dir" / "x.log" + with pytest.raises(logger_mod.LogFileError): + init_logger(level="INFO", log_file=str(bad_path)) + + # No half-initialized logger is left behind. + assert logger_mod._initialized is False + assert logger_mod._root_logger is None + assert logger_mod._console_handler is None + assert logger_mod._file_handler is None + assert logging.getLogger("scratchv").handlers == [] + assert capsys.readouterr().err == "" diff --git a/tests/test_logger_wiring.py b/tests/test_logger_wiring.py new file mode 100644 index 0000000..7b35068 --- /dev/null +++ b/tests/test_logger_wiring.py @@ -0,0 +1,234 @@ +"""Wiring tests for compiler structured logging (Topic 07). + +Covers the CLI -> CompilerConfig contract, stderr-only console handler +(R1/R2), end-to-end logging activation (D6) and default-off stability. +""" + +import re +import sys +from pathlib import Path + +import pytest + +import scratchv.utils.logger as logger_mod +from scratchv.compiler import CompilerConfig, CompilerDriver +from scratchv.main import args_to_config, build_arg_parser, main +from scratchv.utils.logger import shutdown + +DSL = (Path(__file__).resolve().parent.parent + / "benchmarks" / "cases" / "001_simple_add.dsl") +ONNX = (Path(__file__).resolve().parent.parent + / "models" / "graph" / "cnn.onnx") + + +@pytest.fixture(autouse=True) +def _logger_teardown(): + yield + shutdown() + + +def test_args_to_config_logging_fields(): + args = build_arg_parser().parse_args( + ["input.dsl", "--log-level", "DEBUG", "--log-file", "x.log"]) + config = args_to_config(args) + assert config.use_logger is True + assert config.log_level == "DEBUG" + assert config.log_file == "x.log" + assert isinstance(config.log_color, bool) + + +def test_log_file_only_implies_logging(): + args = build_arg_parser().parse_args(["input.dsl", "--log-file", "x.log"]) + config = args_to_config(args) + assert config.use_logger is True + assert config.log_level == "INFO" + assert config.log_file == "x.log" + + +def test_invalid_log_level_rejected_by_cli(): + with pytest.raises(SystemExit): + build_arg_parser().parse_args(["input.dsl", "--log-level", "VERBOSE"]) + + +def test_console_handler_targets_stderr(): + logger_mod.init_logger(level="INFO", use_color=False) + assert logger_mod._console_handler is not None + assert logger_mod._console_handler.stream is sys.stderr + shutdown() + + +def test_cli_logging_end_to_end(tmp_path, capsys): + out = tmp_path / "out.s" + log_file = tmp_path / "build.log" + rc = main([str(DSL), "-o", str(out), "--optimize", "all", + "--log-level", "DEBUG", "--log-file", str(log_file)]) + captured = capsys.readouterr() + + assert rc == 0 + assert out.exists() and out.stat().st_size > 0 + assert captured.out == "" + assert "[scratchv.compiler.parse]" in captured.err + assert "done (" in captured.err + assert "[scratchv.compiler.codegen]" in captured.err + assert "[scratchv.compiler.passes]" in captured.err + assert "constant-folding" in captured.err + + text = log_file.read_text() + assert "DEBUG" in text + assert "pass constant-folding" in text + assert re.search(r"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}", text) + + +def test_no_logging_by_default_keeps_outputs_stable(tmp_path, capsys): + out = tmp_path / "out.s" + rc = main([str(DSL), "-o", str(out)]) + captured = capsys.readouterr() + + assert rc == 0 + assert out.exists() + assert captured.out == "" + assert "scratchv.compiler" not in captured.err + assert captured.err.strip() == f"OK RISCV output written to {out}" + + +def test_compile_failure_logged(tmp_path, capsys): + bad = tmp_path / "bad.dsl" + bad.write_text("add(a, b\n", encoding="utf-8") + log_file = tmp_path / "fail.log" + + rc = main([str(bad), "-o", str(tmp_path / "out.s"), + "--log-level", "DEBUG", "--log-file", str(log_file)]) + captured = capsys.readouterr() + + assert rc == 1 + assert captured.out == "" + text = log_file.read_text() + assert "ERROR" in text + assert "compilation failed" in text + assert "error[E" in text + + +def test_parse_failure_logged(tmp_path, monkeypatch, capsys): + def bad_parse(self, input_path, dsl_source=None): + raise ValueError("parse exploded") + + monkeypatch.setattr(CompilerDriver, "_parse", bad_parse) + log_file = tmp_path / "parse.log" + rc = main(["model.onnx", "-o", str(tmp_path / "out.s"), + "--log-level", "DEBUG", "--log-file", str(log_file)]) + capsys.readouterr() + + assert rc == 1 + text = log_file.read_text() + assert "ERROR" in text + assert "compilation failed: parse exploded" in text + + +def test_codegen_failure_logged(tmp_path, monkeypatch, capsys): + def bad_codegen(self, program): + raise ValueError("codegen exploded") + + monkeypatch.setattr(CompilerDriver, "_generate_code", bad_codegen) + log_file = tmp_path / "codegen.log" + rc = main([str(DSL), "-o", str(tmp_path / "out.s"), + "--log-level", "DEBUG", "--log-file", str(log_file)]) + capsys.readouterr() + + assert rc == 1 + text = log_file.read_text() + assert "ERROR" in text + assert "compilation failed: codegen exploded" in text + assert "FAILED" in text + + +def test_log_file_same_as_input_refused(tmp_path, capsys): + src = tmp_path / "input.dsl" + src.write_text(DSL.read_text(encoding="utf-8"), encoding="utf-8") + original = src.read_text(encoding="utf-8") + + rc = main([str(src), "-o", str(tmp_path / "out.s"), + "--log-file", str(src)]) + captured = capsys.readouterr() + + assert rc == 2 + assert src.read_text(encoding="utf-8") == original + assert "log file" in captured.err + assert "would overwrite input" in captured.err + assert "Traceback" not in captured.err + + rc2 = main([str(DSL), "-o", str(tmp_path / "out2.s"), + "--log-file", str(tmp_path / "out2.s")]) + captured2 = capsys.readouterr() + + assert rc2 == 2 + assert "would overwrite output" in captured2.err + + +def test_log_file_bad_path_error(tmp_path, capsys): + bad = tmp_path / "missing_dir" / "x.log" + + rc = main([str(DSL), "-o", str(tmp_path / "out.s"), + "--log-file", str(bad)]) + captured = capsys.readouterr() + + assert rc == 2 + assert "cannot open log file" in captured.err + assert "Traceback" not in captured.err + assert logger_mod._initialized is False + assert logger_mod._root_logger is None + + if ONNX.exists(): + rc2 = main([str(ONNX), "-o", str(tmp_path / "out2.s"), + "--log-file", str(bad)]) + captured2 = capsys.readouterr() + + assert rc2 == 2 + assert "cannot open log file" in captured2.err + assert "Traceback" not in captured2.err + + +def test_driver_reuse_after_shutdown_keeps_file(tmp_path, capsys): + log_file = tmp_path / "reuse.log" + config = CompilerConfig( + use_logger=True, log_level="INFO", + log_file=str(log_file), log_color=False, + ) + driver = CompilerDriver(config) + + first = driver.compile(str(DSL), str(tmp_path / "a.s")) + assert first.success + + shutdown() + capsys.readouterr() + + second = driver.compile(str(DSL), str(tmp_path / "b.s")) + captured = capsys.readouterr() + + assert second.success + # The second run must honour the driver config instead of silently + # falling back to the default logger (no file, colored, INFO). + assert logger_mod._file_handler is not None + assert logger_mod._config.get("log_file") == str(log_file) + assert "\033[" not in captured.err + assert "compilation succeeded" in log_file.read_text() + + +def test_pass_exception_logs_traceback(tmp_path, monkeypatch, capsys): + from scratchv.optimizer.constant_folding import ConstantFolder + + def boom(self): + raise RuntimeError("simulated pass failure") + + monkeypatch.setattr(ConstantFolder, "run", boom) + log_file = tmp_path / "pass.log" + + rc = main([str(DSL), "-o", str(tmp_path / "out.s"), + "--optimize", "all", "--log-level", "DEBUG", + "--log-file", str(log_file)]) + capsys.readouterr() + + assert rc == 0 # E2: the pass failure is swallowed by design + text = log_file.read_text() + assert "pass 'constant-folding' failed" in text + assert "Traceback (most recent call last)" in text + assert "RuntimeError: simulated pass failure" in text diff --git a/tests/test_topic07_logger_case_report.py b/tests/test_topic07_logger_case_report.py new file mode 100644 index 0000000..e703742 --- /dev/null +++ b/tests/test_topic07_logger_case_report.py @@ -0,0 +1,169 @@ +"""Tests for the Topic 07 structured-logging feature case report. + +The report is the CI artifact that proves the compiler logger produces a +complete staged DEBUG record, keeps the generated output byte-identical to +a run without logging, records ERROR on a failing compile, and does not +leak handlers across init/shutdown cycles. +""" + +from __future__ import annotations + +import json +import logging +from pathlib import Path + +import pytest + +import benchmarks.run_topic07_logger_case as case_report +from benchmarks.run_topic07_logger_case import ( + SCHEMA_VERSION, + evaluate, + main, + measure_failure_path, + measure_handler_lifecycle, + measure_logged_run, + measure_plain_run, +) +from scratchv.utils.logger import init_logger, shutdown + +CASE = ( + Path(__file__).resolve().parents[1] + / "benchmarks" / "cases" / "topic07_logger_feature.dsl" +) + + +@pytest.fixture(autouse=True) +def _reset_logging(): + yield + shutdown() + + +def test_logged_compile_records_all_phases_with_debug(tmp_path): + logged = measure_logged_run(CASE, repeats=1, workdir=tmp_path / "logged") + + assert logged["success"] + assert logged["log_file_exists"] and logged["log_file_bytes"] > 0 + assert logged["levels"]["DEBUG"] > 0 + assert logged["levels"]["INFO"] > 0 + assert all(logged["phases"].values()), logged["phases"] + assert all(logged["phase_records"].values()), logged["phase_records"] + assert all(logged["debug_markers"].values()), logged["debug_markers"] + + +def test_ab_outputs_are_byte_identical(tmp_path): + logged = measure_logged_run(CASE, repeats=1, workdir=tmp_path / "logged") + plain = measure_plain_run(CASE, repeats=1, workdir=tmp_path / "plain") + + assert logged["success"] and plain["success"] + assert logged["output_sha256"] == plain["output_sha256"] + assert logged["output_file_sha256"] == plain["output_file_sha256"] + assert logged["output_bytes"] == plain["output_bytes"] + assert (Path(logged["output_file"]).read_bytes() + == Path(plain["output_file"]).read_bytes()) + + +def test_failure_path_records_error_and_exc_info(tmp_path): + failure = measure_failure_path(tmp_path / "failure") + + assert failure["success"] is False + assert failure["error_count"] >= 1 + assert failure["log_file_exists"] + assert failure["has_error_record"] + assert any("compilation failed" in record + for record in failure["error_records"]) + assert failure["output_written"] is False + # The exc_info contract is probed separately from the compiler log. + assert failure["exc_info_has_traceback"] + assert failure["exc_info_has_runtime_error"] + + +def test_hard_check_gate_is_not_vacuous(monkeypatch, tmp_path): + """Broken logging/output must be reported as hard failures.""" + real = measure_logged_run(CASE, repeats=1, workdir=tmp_path / "real") + broken = dict(real) + broken["success"] = False + broken["log_file_exists"] = False + broken["log_file_bytes"] = 0 + broken["levels"] = {name: 0 for name in real["levels"]} + broken["debug_markers"] = {name: False for name in real["debug_markers"]} + broken["output_sha256"] = "0" * 64 + broken["output_file_sha256"] = "0" * 64 + + monkeypatch.setattr( + case_report, "measure_logged_run", lambda *args, **kwargs: broken) + + report = evaluate(CASE, repeats=1) + assert "case_compiles_with_logging" in report["hard_failures"] + assert "log_file_created" in report["hard_failures"] + assert "log_file_contains_debug_records" in report["hard_failures"] + assert "outputs_byte_identical" in report["hard_failures"] + + +def test_evaluate_passes_all_hard_checks(tmp_path): + report = evaluate(CASE, repeats=2) + + assert report["schema_version"] == SCHEMA_VERSION + assert report["topic"] == "topic07-logger" + assert report["hard_failures"] == [] + assert all(report["hard_checks"].values()) + assert report["outputs_equal"] is True + assert report["honesty"] + assert report["runs"] == 2 + assert report["logged"]["handler_counts"] == [2, 2] + assert report["logged"]["handler_count_after_shutdown"] == 0 + assert report["overhead_ms"] == pytest.approx( + report["logged"]["compile_ms_median"] + - report["plain"]["compile_ms_median"], + abs=1e-3, + ) + + +def test_main_writes_json_and_markdown(tmp_path, capsys): + json_path = tmp_path / "report.json" + md_path = tmp_path / "report.md" + + exit_code = main([ + "--case", str(CASE), + "--json", str(json_path), + "--markdown", str(md_path), + "--repeats", "1", + ]) + + assert exit_code == 0 + data = json.loads(json_path.read_text()) + assert data["schema_version"] == SCHEMA_VERSION + assert data["hard_failures"] == [] + assert data["outputs_equal"] is True + markdown = md_path.read_text() + assert "Topic 07 Structured-Logging Feature Case" in markdown + assert "A/B summary" in markdown + assert "Failure path" in markdown + assert "Hard checks" in markdown + assert "Honesty" in markdown + assert "Topic 07 Structured-Logging Feature Case" in ( + capsys.readouterr().out + ) + + +def test_main_rejects_missing_case(tmp_path): + with pytest.raises(SystemExit) as exc: + main(["--case", str(tmp_path / "missing.dsl")]) + + assert exc.value.code == 2 + + +def test_repeated_init_shutdown_does_not_leak_handlers(tmp_path): + lifecycle = measure_handler_lifecycle(tmp_path / "lifecycle") + + assert lifecycle["handler_counts"] == [1, 1, 1, 2, 2, 2] + assert lifecycle["max_handlers"] == 2 + assert lifecycle["after_shutdown"] == 0 + assert lifecycle["leaked"] is False + + # Direct double-init check: the old handlers must be released first. + init_logger(level="INFO", use_color=False) + assert len(logging.getLogger("scratchv").handlers) == 1 + init_logger(level="INFO", use_color=False) + assert len(logging.getLogger("scratchv").handlers) == 1 + shutdown() + assert len(logging.getLogger("scratchv").handlers) == 0