feedBack/docs/plugin-logging.md
Miguel_LZPF b45751164f
fix: address PR #332 review feedback
Addresses 12 of 13 review comments from Copilot and CodeRabbit on
PR #332. One comment (no-manifests in validate-plugins.yml) is
declined and answered inline; the rest are applied here.

Substantive fixes:

- .github/workflows/validate-plugins.yml — add --noconftest to the
  schema-tests step. tests/conftest.py imports structlog at module
  level, but the CI job only installs requirements-test.txt
  (pytest/httpx/jsonschema), so pytest collection would fail at
  conftest import. The schema tests don't use shared fixtures, so
  skipping conftest is safe and avoids dragging the full runtime
  requirements into a 2 KB validation job. (Copilot)

- schema/plugin.schema.json — tighten the server_files regex on both
  settings.server_files and diagnostics.server_files to match the
  runtime _validate_relpath rules in plugins/__init__.py. The
  previous regex only blocked absolute paths, drive letters,
  backslashes, and "..". The runtime also rejects "//", "./",
  "/./", and leading-dotfile segments. Schema-valid manifests are
  now also load-time-valid. Verified the regex against 12 cases:
  the 3 in-tree manifests still validate. (Copilot)

- .claude/skills/plugin-validate/SKILL.md — add a per-iteration
  plugin_ok flag so we no longer print "OK <path>" after an earlier
  FAIL in the same manifest. Schema-pass + id-mismatch previously
  produced both FAIL and OK lines for one plugin. (CodeRabbit)

- docs/websocket-protocol.md — clarify song_info.tuning array length
  is source-dependent (typically 6 guitar, 4 bass, but extended-range
  GP imports can be 7/8/5/6). Recommend highway.getStringCount() for
  the authoritative count. Line 30 already said this; the table row
  on line 12 was the stale half. (CodeRabbit)

Trivial fixes:

- .claude/rules/plugin-author.md — "wants included" -> "wants to
  include" in the settings.server_files rule. (CodeRabbit)

- Markdown MD040 — add `text` language tags to 7 bare-fence code
  blocks across AGENTS.md, docs/PLUGIN_AUTHORING.md,
  docs/testing-plugins.md, docs/plugin-logging.md, .claude/README.md,
  .claude/agents/slopsmith-reviewer.md, and
  .claude/skills/plugin-validate/SKILL.md (two fences). (CodeRabbit)

Declined:

- .github/workflows/validate-plugins.yml no-manifests -> exit 0
  (CodeRabbit suggested exit 1). Plugins in this repo are in-tree,
  not submodules (no .gitmodules, git submodule status empty), and
  the workflow has a path filter on plugins/**/plugin.json so it
  only runs when a manifest actually changes. Exit 0 is correct.
  Answered inline on the PR.

Verification:
  pytest tests/test_plugin_schema.py -v --noconftest    # 8 passed
  python -c "import json,glob,jsonschema; s=json.load(open('schema/plugin.schema.json')); [jsonschema.validate(json.load(open(p)), s) for p in sorted(glob.glob('plugins/*/plugin.json'))]"
  # ok — all 3 in-tree manifests validate against tightened schema
Signed-off-by: Miguel_LZPF <mgcdreamer@gmail.com>
2026-06-18 00:38:51 -07:00

2.9 KiB

Plugin logging

Use context["log"] for all backend plugin output. It is a stdlib logging.Logger namespaced to slopsmith.plugin.<id>, pre-configured with the app-wide level, format (including JSON mode), and correlation IDs. Never use print() — it bypasses correlation context and log rotation.

Backend usage

def setup(app, context):
    log = context["log"]
    log.info("plugin ready")
    log.warning("optional dependency %r not found, feature disabled", dep)
    try:
        risky_init()
    except Exception:
        log.exception("unhandled error during setup")  # auto-captures traceback

CLI entry-point fallback

For helper scripts that also run as __main__, add a stdlib fallback so the logger works without the server pipeline:

if __name__ == "__main__":
    import logging
    logging.basicConfig(level=logging.INFO, format="%(levelname)s %(message)s")

How it's wired

The plugin loader assigns each plugin a logger before calling setup():

context["log"] = logging.getLogger(f"slopsmith.plugin.{plugin_id}")

That logger inherits from the root slopsmith logger, which is configured by logging_setup.configure_logging() (called from main.py before uvicorn boots). It respects:

  • LOG_LEVELDEBUG | INFO | WARNING | ERROR (default INFO)
  • LOG_FORMATjson | text (default text — coloured console)
  • LOG_FILE — optional path for a persistent log file (e.g. /config/slopsmith.log)
  • Correlation IDs — each HTTP request carries X-Request-ID; structlog injects it into every log line during that request's lifetime. WebSocket sessions get their own ws_conn_id contextvar bound at accept time.

Verifying

Look for your plugin's logger name in the console output:

INFO     slopsmith.plugin.my_plugin: plugin ready

Switch LOG_FORMAT=json to see structured output:

{"timestamp": "...", "level": "info", "logger": "slopsmith.plugin.my_plugin", "event": "plugin ready", "request_id": "..."}

Common mistakes

  • Using print() inside setup() or request handlers. print() goes to stdout, bypasses level filtering, log rotation, JSON formatting, and correlation IDs. Audit your plugin with grep -nR 'print(' plugins/<id>/.
  • Creating a new logger with logging.getLogger("my_plugin"). This creates an unparented logger that doesn't inherit slopsmith's configuration. Always use the one passed via context["log"].
  • Logging at INFO in hot paths. Default LOG_LEVEL is INFO, so log.info(...) inside a per-frame or per-message loop floods output. Use log.debug(...) for hot-path tracing.