fix(logging): bound log size + honor LOG_LEVEL + mute kicad-skip (#181)

The server wrote gigabytes to ~/.kicad-mcp/logs and ignored LOG_LEVEL. Three
root causes, all fixed here (the logging carve-out of #182):

- Python (kicad_interface.py): replace the unbounded FileHandler with a
  RotatingFileHandler (10 MB x 3 backups, env-tunable via KICAD_MCP_LOG_MAX_BYTES
  / KICAD_MCP_LOG_BACKUP_COUNT); read the level from KICAD_MCP_LOG_LEVEL or
  LOG_LEVEL (default INFO) instead of hardcoding DEBUG; mute the noisy
  skip / skip.sexp.* loggers to WARNING unless KICAD_MCP_DEBUG_SKIP is set.
- TypeScript (config.ts): honor KICAD_MCP_LOG_LEVEL / LOG_LEVEL for the TS logger.
- TypeScript (logger.ts): size-cap the per-day log files with the same env knobs.
- Docs + a no-network test for the env helpers, skip muting, and that no
  unbounded handler targets kicad_interface.log.

Verified: LOG_LEVEL is now applied, skip is muted, and the file rotates instead
of growing forever. Full suite unchanged from baseline.

The hierarchical-sheet rewrite from #182 is intentionally left out (stays as a
separate PR pending the #169/#170 design discussion).

Co-Authored-By: angelorodem <angelorodem@users.noreply.github.com>
Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
mixelpixx
2026-05-30 12:07:03 -04:00
parent 5493a37024
commit f95de32cdd
5 changed files with 286 additions and 12 deletions

View File

@@ -1307,6 +1307,16 @@ See [STATUS_SUMMARY.md](docs/STATUS_SUMMARY.md) for the complete status matrix a
**Developer Mode:** **Developer Mode:**
Set `KICAD_MCP_DEV=1` to capture MCP session logs for debugging. See CHANGELOG v2.2.3 for details. 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. See [ROADMAP.md](docs/ROADMAP.md) for planned features.
## What Do You Want to See Next? ## What Do You Want to See Next?

View File

@@ -15,6 +15,7 @@ import shutil
import sys import sys
import traceback import traceback
from datetime import datetime from datetime import datetime
from logging.handlers import RotatingFileHandler
from pathlib import Path from pathlib import Path
from typing import Any, Dict, List, Optional, Tuple from typing import Any, Dict, List, Optional, Tuple
@@ -43,26 +44,93 @@ from schemas.tool_schemas import TOOL_SCHEMAS
_annotation_loader = AnnotationLoader() _annotation_loader = AnnotationLoader()
# Configure logging
# Try to set up a file handler in ~/.kicad-mcp/logs. If that directory isn't def _parse_log_level() -> int:
# writable (e.g. sandboxed test environments, restricted CI runners), fall """Return the configured Python log level from the MCP environment.
# back to console-only logging so importing this module never crashes.
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: try:
log_dir = os.path.join(os.path.expanduser("~"), ".kicad-mcp", "logs") log_dir = os.path.join(os.path.expanduser("~"), ".kicad-mcp", "logs")
os.makedirs(log_dir, exist_ok=True) os.makedirs(log_dir, exist_ok=True)
log_file = os.path.join(log_dir, "kicad_interface.log") 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( logging.basicConfig(
level=logging.DEBUG, level=_LOG_LEVEL,
format="%(asctime)s [%(levelname)s] %(message)s", format="%(asctime)s [%(levelname)s] %(message)s",
handlers=[logging.FileHandler(log_file)], handlers=[log_handler],
force=True,
) )
except (OSError, PermissionError): except (OSError, PermissionError):
logging.basicConfig( logging.basicConfig(
level=logging.DEBUG, level=_LOG_LEVEL,
format="%(asctime)s [%(levelname)s] %(message)s", format="%(asctime)s [%(levelname)s] %(message)s",
force=True,
) )
logger = logging.getLogger("kicad_interface") 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 # Log Python environment details
logger.info(f"Python version: {sys.version}") logger.info(f"Python version: {sys.version}")
logger.info(f"Python executable: {sys.executable}") logger.info(f"Python executable: {sys.executable}")

View File

@@ -16,6 +16,9 @@ const __dirname = dirname(__filename);
// Default config location // Default config location
const DEFAULT_CONFIG_PATH = join(dirname(__dirname), "config", "default-config.json"); 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 * Server configuration schema
*/ */
@@ -25,7 +28,7 @@ const ConfigSchema = z.object({
description: z.string().default("MCP server for KiCAD PCB design operations"), description: z.string().default("MCP server for KiCAD PCB design operations"),
pythonPath: z.string().optional(), pythonPath: z.string().optional(),
kicadPath: z.string().optional(), kicadPath: z.string().optional(),
logLevel: z.enum(["error", "warn", "info", "debug"]).default("info"), logLevel: LogLevelSchema.default("info"),
logDir: z.string().optional(), logDir: z.string().optional(),
}); });
@@ -34,6 +37,48 @@ const ConfigSchema = z.object({
*/ */
export type Config = z.infer<typeof ConfigSchema>; export type Config = z.infer<typeof ConfigSchema>;
/**
* 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 * Load configuration from file
* *
@@ -48,7 +93,7 @@ export async function loadConfig(configPath?: string): Promise<Config> {
// Check if file exists // Check if file exists
if (!existsSync(filePath)) { if (!existsSync(filePath)) {
logger.warn(`Configuration file not found: ${filePath}, using defaults`); logger.warn(`Configuration file not found: ${filePath}, using defaults`);
return ConfigSchema.parse({}); return applyEnvironmentOverrides(ConfigSchema.parse({}));
} }
// Read and parse configuration // Read and parse configuration
@@ -56,11 +101,11 @@ export async function loadConfig(configPath?: string): Promise<Config> {
const config = JSON.parse(configData); const config = JSON.parse(configData);
// Validate configuration // Validate configuration
return ConfigSchema.parse(config); return applyEnvironmentOverrides(ConfigSchema.parse(config));
} catch (error) { } catch (error) {
logger.error(`Error loading configuration: ${error}`); logger.error(`Error loading configuration: ${error}`);
// Return default configuration // Return default configuration
return ConfigSchema.parse({}); return applyEnvironmentOverrides(ConfigSchema.parse({}));
} }
} }

View File

@@ -2,7 +2,7 @@
* Logger for KiCAD MCP server * 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 { join } from "path";
import * as os from "os"; import * as os from "os";
@@ -12,12 +12,49 @@ type LogLevel = "error" | "warn" | "info" | "debug";
// Default log directory // Default log directory
const DEFAULT_LOG_DIR = join(os.homedir(), ".kicad-mcp", "logs"); 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 * Logger class for KiCAD MCP server
*/ */
class Logger { class Logger {
private logLevel: LogLevel = "info"; private logLevel: LogLevel = "info";
private logDir: string = DEFAULT_LOG_DIR; 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 * Set the log level
@@ -103,6 +140,7 @@ class Logger {
} }
const logFile = join(this.logDir, `kicad-mcp-${new Date().toISOString().split("T")[0]}.log`); const logFile = join(this.logDir, `kicad-mcp-${new Date().toISOString().split("T")[0]}.log`);
this.rotateIfNeeded(logFile);
appendFileSync(logFile, formattedMessage + "\n"); appendFileSync(logFile, formattedMessage + "\n");
} catch (error) { } catch (error) {
console.error(`Failed to write to log file: ${error}`); console.error(`Failed to write to log file: ${error}`);

View File

@@ -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)