diff --git a/README.md b/README.md index 5e0b095..a8af65e 100644 --- a/README.md +++ b/README.md @@ -1307,6 +1307,16 @@ See [STATUS_SUMMARY.md](docs/STATUS_SUMMARY.md) for the complete status matrix a **Developer Mode:** Set `KICAD_MCP_DEV=1` to capture MCP session logs for debugging. See CHANGELOG v2.2.3 for details. +**Logging (`~/.kicad-mcp/logs/`):** +Logs default to `INFO` and the file is size-capped so it can't grow without bound. Tune via the MCP server's environment: + +| Variable | Default | Purpose | +| --- | --- | --- | +| `LOG_LEVEL` / `KICAD_MCP_LOG_LEVEL` | `info` | Log verbosity (`error`/`warn`/`info`/`debug`, or `off`). `KICAD_MCP_LOG_LEVEL` wins. | +| `KICAD_MCP_LOG_MAX_BYTES` | `10485760` (10 MB) | Max size per log file before it rotates; `0` disables rotation. | +| `KICAD_MCP_LOG_BACKUP_COUNT` | `3` | Number of rotated backups to keep. | +| `KICAD_MCP_DEBUG_SKIP` | unset | Set to `1` to re-enable the verbose kicad-skip parser DEBUG logs (muted by default). | + See [ROADMAP.md](docs/ROADMAP.md) for planned features. ## What Do You Want to See Next? diff --git a/python/kicad_interface.py b/python/kicad_interface.py index 2450326..2bd1a6f 100644 --- a/python/kicad_interface.py +++ b/python/kicad_interface.py @@ -15,6 +15,7 @@ import shutil import sys import traceback from datetime import datetime +from logging.handlers import RotatingFileHandler from pathlib import Path from typing import Any, Dict, List, Optional, Tuple @@ -43,26 +44,93 @@ from schemas.tool_schemas import TOOL_SCHEMAS _annotation_loader = AnnotationLoader() -# Configure logging -# Try to set up a file handler in ~/.kicad-mcp/logs. If that directory isn't -# writable (e.g. sandboxed test environments, restricted CI runners), fall -# back to console-only logging so importing this module never crashes. + +def _parse_log_level() -> int: + """Return the configured Python log level from the MCP environment. + + Honors KICAD_MCP_LOG_LEVEL (preferred) or LOG_LEVEL; defaults to INFO. + Accepts common aliases (WARN, FATAL) and an OFF/NONE/0 kill switch. + """ + raw_level = os.environ.get("KICAD_MCP_LOG_LEVEL") or os.environ.get("LOG_LEVEL") or "INFO" + normalized = raw_level.strip().upper() + aliases = { + "WARN": "WARNING", + "FATAL": "CRITICAL", + "OFF": "OFF", + "NONE": "OFF", + "FALSE": "OFF", + "0": "OFF", + } + normalized = aliases.get(normalized, normalized) + if normalized == "OFF": + return logging.CRITICAL + 1 + return { + "CRITICAL": logging.CRITICAL, + "ERROR": logging.ERROR, + "WARNING": logging.WARNING, + "INFO": logging.INFO, + "DEBUG": logging.DEBUG, + }.get(normalized, logging.INFO) + + +def _parse_positive_int_env(name: str, default: int) -> int: + """Return a non-negative int from env var ``name``, or ``default``.""" + try: + value = int(os.environ.get(name, str(default))) + except ValueError: + return default + return value if value >= 0 else default + + +def _env_flag_enabled(name: str) -> bool: + """Return True when env var ``name`` is a truthy flag (1/true/yes/on).""" + return os.environ.get(name, "").strip().lower() in {"1", "true", "yes", "on"} + + +_LOG_LEVEL = _parse_log_level() + +# Configure logging. +# The file handler rotates (default 10 MB x 3 backups) so the log can never +# grow without bound (issue #181); the level honors the environment instead of +# being hardcoded to DEBUG. If ~/.kicad-mcp/logs isn't writable (sandboxed test +# envs, restricted CI runners) we fall back to console-only logging so importing +# this module never crashes. try: log_dir = os.path.join(os.path.expanduser("~"), ".kicad-mcp", "logs") os.makedirs(log_dir, exist_ok=True) log_file = os.path.join(log_dir, "kicad_interface.log") + max_log_bytes = _parse_positive_int_env("KICAD_MCP_LOG_MAX_BYTES", 10 * 1024 * 1024) + backup_count = _parse_positive_int_env("KICAD_MCP_LOG_BACKUP_COUNT", 3) + if max_log_bytes: + log_handler: logging.Handler = RotatingFileHandler( + log_file, + maxBytes=max_log_bytes, + backupCount=backup_count, + encoding="utf-8", + ) + else: + log_handler = logging.FileHandler(log_file, encoding="utf-8") logging.basicConfig( - level=logging.DEBUG, + level=_LOG_LEVEL, format="%(asctime)s [%(levelname)s] %(message)s", - handlers=[logging.FileHandler(log_file)], + handlers=[log_handler], + force=True, ) except (OSError, PermissionError): logging.basicConfig( - level=logging.DEBUG, + level=_LOG_LEVEL, format="%(asctime)s [%(levelname)s] %(message)s", + force=True, ) logger = logging.getLogger("kicad_interface") +# kicad-skip's S-expression parser emits per-node DEBUG logs that can fill disks +# during hierarchy traversal (issue #181). Keep those quiet unless explicitly +# enabled via KICAD_MCP_DEBUG_SKIP. +_SKIP_LOG_LEVEL = logging.DEBUG if _env_flag_enabled("KICAD_MCP_DEBUG_SKIP") else logging.WARNING +for _skip_logger_name in ("skip", "skip.sexp", "skip.sexp.parser", "skip.sexp.sourcefile"): + logging.getLogger(_skip_logger_name).setLevel(_SKIP_LOG_LEVEL) + # Log Python environment details logger.info(f"Python version: {sys.version}") logger.info(f"Python executable: {sys.executable}") diff --git a/src/config.ts b/src/config.ts index ac4aeb0..18c6793 100644 --- a/src/config.ts +++ b/src/config.ts @@ -16,6 +16,9 @@ const __dirname = dirname(__filename); // Default config location const DEFAULT_CONFIG_PATH = join(dirname(__dirname), "config", "default-config.json"); +const LOG_LEVEL_VALUES = ["error", "warn", "info", "debug"] as const; +const LogLevelSchema = z.enum(LOG_LEVEL_VALUES); + /** * Server configuration schema */ @@ -25,7 +28,7 @@ const ConfigSchema = z.object({ description: z.string().default("MCP server for KiCAD PCB design operations"), pythonPath: z.string().optional(), kicadPath: z.string().optional(), - logLevel: z.enum(["error", "warn", "info", "debug"]).default("info"), + logLevel: LogLevelSchema.default("info"), logDir: z.string().optional(), }); @@ -34,6 +37,48 @@ const ConfigSchema = z.object({ */ export type Config = z.infer; +/** + * Read the log level from the environment (KICAD_MCP_LOG_LEVEL or LOG_LEVEL), + * normalizing "warning" -> "warn". Returns undefined when unset/invalid so the + * file/default value is kept. + */ +function getEnvLogLevel(): Config["logLevel"] | undefined { + for (const envName of ["KICAD_MCP_LOG_LEVEL", "LOG_LEVEL"] as const) { + const rawLevel = process.env[envName]; + if (!rawLevel) { + continue; + } + + const normalized = rawLevel.trim().toLowerCase(); + const level = normalized === "warning" ? "warn" : normalized; + const parsed = LogLevelSchema.safeParse(level); + if (!parsed.success) { + const acceptedValues = [...LOG_LEVEL_VALUES, "warning"].join(", "); + logger.warn( + `Ignoring invalid ${envName} value: ${rawLevel}. Expected one of: ${acceptedValues}`, + ); + continue; + } + + return parsed.data; + } + + return undefined; +} + +/** + * Apply environment-based overrides on top of a loaded config. The env log + * level (if set) wins over the file/default so users can control verbosity + * without editing the config file. + */ +function applyEnvironmentOverrides(config: Config): Config { + const envLogLevel = getEnvLogLevel(); + if (!envLogLevel) { + return config; + } + return { ...config, logLevel: envLogLevel }; +} + /** * Load configuration from file * @@ -48,7 +93,7 @@ export async function loadConfig(configPath?: string): Promise { // Check if file exists if (!existsSync(filePath)) { logger.warn(`Configuration file not found: ${filePath}, using defaults`); - return ConfigSchema.parse({}); + return applyEnvironmentOverrides(ConfigSchema.parse({})); } // Read and parse configuration @@ -56,11 +101,11 @@ export async function loadConfig(configPath?: string): Promise { const config = JSON.parse(configData); // Validate configuration - return ConfigSchema.parse(config); + return applyEnvironmentOverrides(ConfigSchema.parse(config)); } catch (error) { logger.error(`Error loading configuration: ${error}`); // Return default configuration - return ConfigSchema.parse({}); + return applyEnvironmentOverrides(ConfigSchema.parse({})); } } diff --git a/src/logger.ts b/src/logger.ts index 7246152..a24ec12 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -2,7 +2,7 @@ * Logger for KiCAD MCP server */ -import { existsSync, mkdirSync, appendFileSync } from "fs"; +import { existsSync, mkdirSync, appendFileSync, statSync, renameSync, rmSync } from "fs"; import { join } from "path"; import * as os from "os"; @@ -12,12 +12,49 @@ type LogLevel = "error" | "warn" | "info" | "debug"; // Default log directory const DEFAULT_LOG_DIR = join(os.homedir(), ".kicad-mcp", "logs"); +/** Parse a non-negative integer env var, or fall back to a default. */ +function envInt(name: string, fallback: number): number { + const raw = process.env[name]; + if (raw === undefined) return fallback; + const value = Number.parseInt(raw, 10); + return Number.isFinite(value) && value >= 0 ? value : fallback; +} + /** * Logger class for KiCAD MCP server */ class Logger { private logLevel: LogLevel = "info"; private logDir: string = DEFAULT_LOG_DIR; + // Size cap for the per-day log files (issue #181). Same env knobs as the + // Python side; KICAD_MCP_LOG_MAX_BYTES=0 disables rotation. + private maxBytes: number = envInt("KICAD_MCP_LOG_MAX_BYTES", 10 * 1024 * 1024); + private backupCount: number = envInt("KICAD_MCP_LOG_BACKUP_COUNT", 3); + + /** + * Rotate the day's log file when it exceeds maxBytes so it can't grow + * without bound. Best-effort — never throws (logging must not break). + */ + private rotateIfNeeded(logFile: string): void { + if (this.maxBytes <= 0) return; + try { + if (!existsSync(logFile) || statSync(logFile).size < this.maxBytes) return; + if (this.backupCount <= 0) { + rmSync(logFile, { force: true }); + return; + } + // Drop the oldest, shift .k -> .k+1, then current -> .1 + const oldest = `${logFile}.${this.backupCount}`; + if (existsSync(oldest)) rmSync(oldest, { force: true }); + for (let i = this.backupCount - 1; i >= 1; i--) { + const src = `${logFile}.${i}`; + if (existsSync(src)) renameSync(src, `${logFile}.${i + 1}`); + } + renameSync(logFile, `${logFile}.1`); + } catch { + // best-effort: if rotation fails, keep logging to the existing file + } + } /** * Set the log level @@ -103,6 +140,7 @@ class Logger { } const logFile = join(this.logDir, `kicad-mcp-${new Date().toISOString().split("T")[0]}.log`); + this.rotateIfNeeded(logFile); appendFileSync(logFile, formattedMessage + "\n"); } catch (error) { console.error(`Failed to write to log file: ${error}`); diff --git a/tests/test_logging_config.py b/tests/test_logging_config.py new file mode 100644 index 0000000..b26b4a6 --- /dev/null +++ b/tests/test_logging_config.py @@ -0,0 +1,113 @@ +""" +Regression tests for env-driven, bounded logging (issue #181). + +Before this fix kicad_interface.py hardcoded the log level to DEBUG and used a +plain (unbounded) FileHandler, and the noisy kicad-skip loggers were never +muted — so ~/.kicad-mcp/logs grew to gigabytes and LOG_LEVEL was ignored. + +These tests exercise the env-parsing helpers, the skip-logger muting, and that +no unbounded file handler is installed. No real KiCAD required. +""" + +import logging +import sys +from logging.handlers import RotatingFileHandler +from pathlib import Path + +import pytest + +sys.path.insert(0, str(Path(__file__).parent.parent / "python")) + +from kicad_interface import ( # noqa: E402 + _env_flag_enabled, + _parse_log_level, + _parse_positive_int_env, +) + + +@pytest.mark.unit +class TestParseLogLevel: + def test_defaults_to_info_when_unset(self, monkeypatch): + monkeypatch.delenv("KICAD_MCP_LOG_LEVEL", raising=False) + monkeypatch.delenv("LOG_LEVEL", raising=False) + assert _parse_log_level() == logging.INFO + + def test_reads_log_level_env(self, monkeypatch): + monkeypatch.delenv("KICAD_MCP_LOG_LEVEL", raising=False) + monkeypatch.setenv("LOG_LEVEL", "warning") + assert _parse_log_level() == logging.WARNING + + def test_kicad_mcp_log_level_takes_precedence(self, monkeypatch): + monkeypatch.setenv("LOG_LEVEL", "debug") + monkeypatch.setenv("KICAD_MCP_LOG_LEVEL", "error") + assert _parse_log_level() == logging.ERROR + + def test_case_insensitive_and_aliases(self, monkeypatch): + monkeypatch.delenv("KICAD_MCP_LOG_LEVEL", raising=False) + for raw, expected in [ + ("debug", logging.DEBUG), + ("INFO", logging.INFO), + ("Warn", logging.WARNING), + ("FATAL", logging.CRITICAL), + ]: + monkeypatch.setenv("LOG_LEVEL", raw) + assert _parse_log_level() == expected + + def test_off_disables_logging(self, monkeypatch): + monkeypatch.delenv("KICAD_MCP_LOG_LEVEL", raising=False) + for raw in ("OFF", "none", "0", "false"): + monkeypatch.setenv("LOG_LEVEL", raw) + assert _parse_log_level() > logging.CRITICAL + + def test_garbage_falls_back_to_info(self, monkeypatch): + monkeypatch.delenv("KICAD_MCP_LOG_LEVEL", raising=False) + monkeypatch.setenv("LOG_LEVEL", "verbose-ish") + assert _parse_log_level() == logging.INFO + + +@pytest.mark.unit +class TestEnvHelpers: + def test_positive_int_valid(self, monkeypatch): + monkeypatch.setenv("X_BYTES", "2048") + assert _parse_positive_int_env("X_BYTES", 10) == 2048 + + def test_positive_int_negative_and_garbage_use_default(self, monkeypatch): + monkeypatch.setenv("X_BYTES", "-5") + assert _parse_positive_int_env("X_BYTES", 10) == 10 + monkeypatch.setenv("X_BYTES", "lots") + assert _parse_positive_int_env("X_BYTES", 10) == 10 + + def test_positive_int_unset_uses_default(self, monkeypatch): + monkeypatch.delenv("X_BYTES", raising=False) + assert _parse_positive_int_env("X_BYTES", 7) == 7 + + def test_flag_truthy_values(self, monkeypatch): + for raw in ("1", "true", "YES", "On"): + monkeypatch.setenv("X_FLAG", raw) + assert _env_flag_enabled("X_FLAG") is True + + def test_flag_falsey_values(self, monkeypatch): + for raw in ("0", "false", "no", ""): + monkeypatch.setenv("X_FLAG", raw) + assert _env_flag_enabled("X_FLAG") is False + monkeypatch.delenv("X_FLAG", raising=False) + assert _env_flag_enabled("X_FLAG") is False + + +@pytest.mark.unit +class TestLoggingSideEffects: + def test_skip_loggers_muted_by_default(self): + # Importing kicad_interface (no KICAD_MCP_DEBUG_SKIP in the test env) + # must have set the noisy kicad-skip loggers to WARNING. + for name in ("skip", "skip.sexp", "skip.sexp.parser", "skip.sexp.sourcefile"): + assert logging.getLogger(name).level == logging.WARNING + + def test_no_unbounded_handler_for_kicad_log(self): + # The regression was a plain logging.FileHandler on kicad_interface.log + # that grows forever. Any handler targeting that file must rotate. + # (Unrelated handlers, e.g. a NUL-device sink from the test harness, + # are ignored — they can't grow.) + for handler in logging.getLogger().handlers: + base = getattr(handler, "baseFilename", "") + if base and base.endswith("kicad_interface.log"): + assert isinstance(handler, RotatingFileHandler)