diff --git a/Sensor/CONTRIBUTING.md b/Sensor/CONTRIBUTING.md index 2b5154d..e39e3fd 100644 --- a/Sensor/CONTRIBUTING.md +++ b/Sensor/CONTRIBUTING.md @@ -169,7 +169,8 @@ logger.warning("[MY_AGENT] Skipped unreadable file", extra={"phase": "parse"}) - Use `WARNING` for recoverable problems (a skipped file or record) and `ERROR` when a whole source or output step fails. Keep recording fixed diagnostic codes with `record_diagnostic()`; log messages do not replace them. -- Never log prompts, tool arguments or results, or other captured content. +- Never log prompts, tool arguments or results, or other captured content. With + `--log-file`, messages are persisted to `sensor_runtime_*.jsonl`. - Explicit report output, such as `AgentObserver.display_summary()`, stays as `print()`. ## Testing Guidelines diff --git a/Sensor/README.md b/Sensor/README.md index ff4ac8e..89cbbd2 100644 --- a/Sensor/README.md +++ b/Sensor/README.md @@ -450,6 +450,29 @@ session IDs, exception messages, or tracebacks. This is a separate operational schema, **not redaction of captured telemetry**. Legacy console previews/errors and older entries already present in `error.log` are not sanitized by this change. +### Runtime log files + +`--log-file` also writes the run's log messages as JSON lines next to the +diagnostics: `sensor_runtime_errors.jsonl` holds warnings and errors, and +`sensor_runtime_debug.jsonl` holds debug and info messages whatever the console +`--log-level` is. Each file rotates at 1 MiB with two backups. Runtime logging is +off by default. If the files cannot be opened, the sensor prints one warning and +keeps printing warnings and errors to stderr. + +Each record has `timestamp`, `level`, `component`, `function`, `phase`, +`sensor_version`, `exception_type`, `message` and, for errors with a traceback, +`stack`: + +```json +{"timestamp":"2026-01-01T12:00:00.000+00:00","level":"WARNING","component":"parsers.cline_parser","function":"parse_all","phase":null,"sensor_version":"0.1.0","exception_type":"KeyError","message":"[CLINE] Error parsing task /home/me/.cline/tasks/123: 'ts'"} +``` + +**Privacy:** unlike the diagnostics above, `message` and `stack` can contain local +file paths and error text. Log call sites do not log prompts or tool content, but +treat these files like other local logs. `--log-file-content-free` drops `message` +and `stack` and keeps the remaining fields. `--log-identity` adds `username` and +`hostname` to each record; it is opt-in because it identifies the machine and user. + ## Output Schema ### AgentEvent diff --git a/Sensor/adr_sensor/cli.py b/Sensor/adr_sensor/cli.py index 656ed0d..357feb1 100644 --- a/Sensor/adr_sensor/cli.py +++ b/Sensor/adr_sensor/cli.py @@ -29,7 +29,7 @@ from .exporters.delivery_checkpoint import DeliveryCheckpoint, DeliveryCheckpointError from .exporters.opentelemetry import OpenTelemetryExportError, OpenTelemetryLogExporter from .observer import AgentObserver -from .sensor_log import append_rotating_line, set_console_level +from .sensor_log import append_rotating_line, disable_runtime_log, enable_runtime_log, set_console_level logger = logging.getLogger(__name__) @@ -125,9 +125,33 @@ def main(): verbosity.add_argument( "-q", "--quiet", action="store_true", help="Print only warnings and errors (same as --log-level warning)" ) + parser.add_argument( + "--log-file", + action="store_true", + help="Also write runtime logs as rotating JSON lines (sensor_runtime_*.jsonl) in the output directory", + ) + parser.add_argument( + "--log-file-content-free", + action="store_true", + help="Omit messages and tracebacks from --log-file records (no paths or error text)", + ) + parser.add_argument( + "--log-identity", + action="store_true", + help="Add the local username and hostname to --log-file records", + ) args = parser.parse_args() + for option in ("log_file_content_free", "log_identity"): + if getattr(args, option) and not args.log_file: + parser.error(f"--{option.replace('_', '-')} requires --log-file") set_console_level("warning" if args.quiet else args.log_level) + if args.log_file: + enable_runtime_log( + args.output_dir or Path.cwd() / "output", + include_details=not args.log_file_content_free, + include_identity=args.log_identity, + ) otel_config = None if args.otel_config is not None: @@ -322,6 +346,7 @@ def _delta(attr: str) -> float: append_rotating_line(log_path, json.dumps(record, separators=(",", ":"), ensure_ascii=False)) except Exception: pass + disable_runtime_log() if __name__ == "__main__": diff --git a/Sensor/adr_sensor/sensor_log.py b/Sensor/adr_sensor/sensor_log.py index 1c70ed6..892448e 100644 --- a/Sensor/adr_sensor/sensor_log.py +++ b/Sensor/adr_sensor/sensor_log.py @@ -19,12 +19,20 @@ ``diagnostics.py``: they describe what the sensor did, not how healthy a run was. """ +import getpass +import json import logging +import socket import sys +from datetime import datetime, timezone from logging.handlers import RotatingFileHandler from pathlib import Path +from . import __version__ + LOGGER_NAME = "adr_sensor" +RUNTIME_ERRORS_LOG = "sensor_runtime_errors.jsonl" +RUNTIME_DEBUG_LOG = "sensor_runtime_debug.jsonl" # Size-based rotation shared by the sensor's append-only files. MAX_LOG_BYTES = 1024 * 1024 @@ -68,6 +76,65 @@ def component_for(record: logging.LogRecord) -> str: return name[len(prefix) :] if name.startswith(prefix) else name +def _exception_type(record: logging.LogRecord): + """Name the exception attached to *record*, or the first one passed as an argument.""" + if record.exc_info and record.exc_info[0] is not None: + return record.exc_info[0].__name__ + args = record.args if isinstance(record.args, tuple) else () + for arg in args: + if isinstance(arg, BaseException): + return type(arg).__name__ + return None + + +def _local_identity(): + """Return the local ``(username, hostname)``, with ``None`` for unknown parts.""" + try: + username = getpass.getuser() + except Exception: + username = None + try: + hostname = socket.gethostname() or None + except OSError: + hostname = None + return username, hostname + + +class JsonRecordFormatter(logging.Formatter): + """Format records as one JSON object per line for the runtime log files. + + Every record carries ``timestamp``, ``level``, ``component``, ``function``, + ``phase``, ``sensor_version`` and ``exception_type``. The rendered + ``message`` and, when an exception is attached, its ``stack`` are included + unless *include_details* is false, which keeps records free of paths and + error text. *include_identity* adds the local ``username`` and ``hostname``, + looked up once. + """ + + def __init__(self, *, include_details: bool = True, include_identity: bool = False) -> None: + super().__init__() + self.include_details = include_details + self.identity = _local_identity() if include_identity else None + + def format(self, record: logging.LogRecord) -> str: + data = { + "timestamp": datetime.fromtimestamp(record.created, timezone.utc).isoformat(timespec="milliseconds"), + "level": record.levelname, + "component": component_for(record), + "function": record.funcName, + "phase": getattr(record, "phase", None), + "sensor_version": __version__, + "exception_type": _exception_type(record), + } + if self.include_details: + data["message"] = record.getMessage() + if record.exc_info: + data["stack"] = self.formatException(record.exc_info) + if self.identity is not None: + data["username"], data["hostname"] = self.identity + return json.dumps(data, ensure_ascii=False, separators=(",", ":"), default=str) + + def _console_handlers(): return [handler for handler in logger.handlers if isinstance(handler, _StdStreamHandler)] @@ -96,6 +163,65 @@ def set_console_level(level) -> None: handler.setLevel(level) +class _RuntimeFileHandler(RotatingFileHandler): + """Rotating runtime log file that never interrupts or floods a run.""" + + def handleError(self, record: logging.LogRecord) -> None: + if getattr(self, "_reported_error", False): + return + self._reported_error = True + sys.stderr.write(f"[ADR] Unable to write the runtime log {Path(self.baseFilename).name}; continuing.\n") + + +def _runtime_handlers(): + return [handler for handler in logger.handlers if isinstance(handler, _RuntimeFileHandler)] + + +def disable_runtime_log() -> None: + """Detach and close the runtime log files, if any.""" + for handler in _runtime_handlers(): + logger.removeHandler(handler) + try: + handler.close() + except (OSError, ValueError): + pass + + +def enable_runtime_log(directory: Path, *, include_details: bool = True, include_identity: bool = False) -> bool: + """Also write sensor log records to rotating JSON-lines files in *directory*. + + WARNING and above go to ``sensor_runtime_errors.jsonl``; DEBUG and INFO go + to ``sensor_runtime_debug.jsonl`` whatever the console level is. Each file + rotates at 1 MiB with two backups. Calling it again replaces the previous + files. If the files cannot be opened, warnings and errors still reach + stderr through the console handlers and this returns ``False``. + """ + disable_runtime_log() + formatter = JsonRecordFormatter(include_details=include_details, include_identity=include_identity) + handlers = [] + try: + directory = Path(directory) + directory.mkdir(parents=True, exist_ok=True) + for name, level_filter in ( + (RUNTIME_ERRORS_LOG, _WarningAndAboveFilter()), + (RUNTIME_DEBUG_LOG, _BelowWarningFilter()), + ): + handler = _RuntimeFileHandler( + directory / name, maxBytes=MAX_LOG_BYTES, backupCount=LOG_BACKUP_COUNT, encoding="utf-8" + ) + handler.addFilter(level_filter) + handler.setFormatter(formatter) + handlers.append(handler) + except OSError: + for handler in handlers: + handler.close() + logger.warning("[ADR] Unable to open the runtime log; warnings and errors are printed to stderr only.") + return False + for handler in handlers: + logger.addHandler(handler) + return True + + def append_rotating_line( path: Path, line: str, *, max_bytes: int = MAX_LOG_BYTES, backup_count: int = LOG_BACKUP_COUNT ) -> None: diff --git a/Sensor/tests/test_sensor_log.py b/Sensor/tests/test_sensor_log.py index d0bb7b8..66cc277 100644 --- a/Sensor/tests/test_sensor_log.py +++ b/Sensor/tests/test_sensor_log.py @@ -1,14 +1,16 @@ """Tests for the leveled sensor logger.""" import importlib +import json import logging import pkgutil +import sys from unittest.mock import patch import pytest import adr_sensor.parsers as parsers -from adr_sensor import sensor_log +from adr_sensor import __version__, sensor_log from adr_sensor.cli import main @@ -138,3 +140,208 @@ def test_every_parser_logs_through_a_sensor_child_logger(): continue module = importlib.import_module(f"adr_sensor.parsers.{module_info.name}") assert module.logger.name == f"adr_sensor.parsers.{module_info.name}" + + +def _record(msg="[EXAMPLE] Error reading %s: %s", args=("/tmp/example.jsonl", OSError("denied")), **extra): + record = logging.LogRecord("adr_sensor.parsers.example_parser", logging.WARNING, "", 0, msg, args, None) + record.funcName = "parse_all" + record.__dict__.update(extra) + return record + + +def test_json_formatter_includes_the_message_by_default(): + data = json.loads(sensor_log.JsonRecordFormatter().format(_record(phase="parse"))) + assert data["level"] == "WARNING" + assert data["component"] == "parsers.example_parser" + assert data["function"] == "parse_all" + assert data["phase"] == "parse" + assert data["sensor_version"] == __version__ + assert data["exception_type"] == "OSError" + assert data["message"] == "[EXAMPLE] Error reading /tmp/example.jsonl: denied" + assert "stack" not in data + + +def test_json_formatter_includes_the_stack_of_an_attached_exception(): + try: + raise ValueError("synthetic") + except ValueError: + record = _record(msg="failed", args=()) + record.exc_info = sys.exc_info() + data = json.loads(sensor_log.JsonRecordFormatter().format(record)) + assert data["exception_type"] == "ValueError" + assert "Traceback" in data["stack"] + assert data["stack"].rstrip().endswith("ValueError: synthetic") + + +def test_json_formatter_can_omit_message_and_stack(): + try: + raise ValueError("SECRET_CANARY") + except ValueError: + record = _record() + record.exc_info = sys.exc_info() + line = sensor_log.JsonRecordFormatter(include_details=False).format(record) + data = json.loads(line) + assert "message" not in data and "stack" not in data + assert data["exception_type"] == "ValueError" + assert "SECRET_CANARY" not in line and "/tmp/example.jsonl" not in line + + +@pytest.fixture +def runtime_log(tmp_path): + yield tmp_path + sensor_log.disable_runtime_log() + + +def _lines(path): + return [json.loads(line) for line in path.read_text(encoding="utf-8").splitlines()] + + +def test_runtime_log_splits_records_by_level(runtime_log, capsys): + assert sensor_log.enable_runtime_log(runtime_log) + log = logging.getLogger("adr_sensor.observer") + log.debug("detail") + log.info("progress") + log.warning("skipped") + log.error("failed") + sensor_log.disable_runtime_log() + + debug = _lines(runtime_log / "sensor_runtime_debug.jsonl") + errors = _lines(runtime_log / "sensor_runtime_errors.jsonl") + assert [(r["level"], r["message"]) for r in debug] == [("DEBUG", "detail"), ("INFO", "progress")] + assert [(r["level"], r["message"]) for r in errors] == [("WARNING", "skipped"), ("ERROR", "failed")] + assert "detail" not in capsys.readouterr().out + + +def test_runtime_log_can_be_content_free(runtime_log): + sensor_log.enable_runtime_log(runtime_log, include_details=False) + logging.getLogger("adr_sensor.observer").warning("Error saving session %s", "SECRET_CANARY") + sensor_log.disable_runtime_log() + text = (runtime_log / "sensor_runtime_errors.jsonl").read_text(encoding="utf-8") + assert "SECRET_CANARY" not in text + assert json.loads(text)["component"] == "observer" + + +def test_enabling_the_runtime_log_again_replaces_the_files(runtime_log): + sensor_log.enable_runtime_log(runtime_log / "first") + sensor_log.enable_runtime_log(runtime_log / "second") + logging.getLogger("adr_sensor.cli").warning("once") + sensor_log.disable_runtime_log() + assert len(sensor_log._runtime_handlers()) == 0 + assert (runtime_log / "first" / "sensor_runtime_errors.jsonl").read_text() == "" + assert len(_lines(runtime_log / "second" / "sensor_runtime_errors.jsonl")) == 1 + + +def test_runtime_log_rotates_by_size(runtime_log, monkeypatch): + monkeypatch.setattr(sensor_log, "MAX_LOG_BYTES", 200) + sensor_log.enable_runtime_log(runtime_log) + for index in range(10): + logging.getLogger("adr_sensor.cli").warning("record %d", index) + sensor_log.disable_runtime_log() + assert (runtime_log / "sensor_runtime_errors.jsonl.1").exists() + assert (runtime_log / "sensor_runtime_errors.jsonl.2").exists() + assert not (runtime_log / "sensor_runtime_errors.jsonl.3").exists() + + +def test_unwritable_runtime_log_falls_back_to_stderr(runtime_log, capsys): + blocked = runtime_log / "blocked" + blocked.write_text("not a directory", encoding="utf-8") + assert sensor_log.enable_runtime_log(blocked) is False + logging.getLogger("adr_sensor.cli").error("still visible") + err = capsys.readouterr().err + assert "Unable to open the runtime log" in err + assert "still visible" in err + assert sensor_log._runtime_handlers() == [] + + +def test_runtime_log_write_failure_is_reported_once(runtime_log, capsys): + sensor_log.enable_runtime_log(runtime_log) + class _FullDisk: + def write(self, text): + raise OSError("no space left on device") + + def flush(self): + raise OSError("no space left on device") + + for handler in sensor_log._runtime_handlers(): + handler.stream.close() + handler.stream = _FullDisk() + log = logging.getLogger("adr_sensor.cli") + log.warning("first") + log.warning("second") + err = capsys.readouterr().err + assert err.count("Unable to write the runtime log sensor_runtime_errors.jsonl") == 1 + assert "first\n" in err and "second\n" in err + + +def _run_cli(tmp_path, monkeypatch, *flags): + def ingest_all(source): + logging.getLogger("adr_sensor.parsers.example_parser").warning( + "[EXAMPLE] Error reading %s: %s", "/synthetic/path.jsonl", OSError("denied") + ) + return [], [] + + monkeypatch.setattr("sys.argv", ["adr-sensor", "--no-save", "--output-dir", str(tmp_path), *flags]) + with patch("adr_sensor.cli.AgentObserver") as observer_cls: + observer_cls.return_value.has_errors = False + observer_cls.return_value.ingest_all.side_effect = ingest_all + main() + + +def test_cli_log_file_writes_runtime_logs_to_the_output_dir(tmp_path, monkeypatch): + _run_cli(tmp_path, monkeypatch, "--log-file") + errors = _lines(tmp_path / "sensor_runtime_errors.jsonl") + assert errors[0]["message"] == "[EXAMPLE] Error reading /synthetic/path.jsonl: denied" + assert any(r["message"].strip() == "ADR Sensor complete!" for r in _lines(tmp_path / "sensor_runtime_debug.jsonl")) + assert sensor_log._runtime_handlers() == [] + + +def test_cli_log_file_content_free_omits_messages(tmp_path, monkeypatch): + _run_cli(tmp_path, monkeypatch, "--log-file", "--log-file-content-free") + text = (tmp_path / "sensor_runtime_errors.jsonl").read_text(encoding="utf-8") + assert "/synthetic/path.jsonl" not in text + assert json.loads(text)["exception_type"] == "OSError" + + +def test_cli_writes_no_runtime_log_by_default(tmp_path, monkeypatch): + _run_cli(tmp_path, monkeypatch) + assert not list(tmp_path.glob("sensor_runtime_*")) + + +def test_cli_log_file_content_free_requires_log_file(monkeypatch): + monkeypatch.setattr("sys.argv", ["adr-sensor", "--log-file-content-free"]) + with pytest.raises(SystemExit) as error: + main() + assert error.value.code == 2 + + +def test_json_formatter_adds_identity_only_when_asked(monkeypatch): + monkeypatch.setattr(sensor_log.getpass, "getuser", lambda: "synthetic-user") + monkeypatch.setattr(sensor_log.socket, "gethostname", lambda: "synthetic-host") + plain = json.loads(sensor_log.JsonRecordFormatter().format(_record())) + with_identity = json.loads(sensor_log.JsonRecordFormatter(include_identity=True).format(_record())) + assert "username" not in plain and "hostname" not in plain + assert (with_identity["username"], with_identity["hostname"]) == ("synthetic-user", "synthetic-host") + + +def test_json_formatter_tolerates_an_unknown_user(monkeypatch): + def no_user(): + raise OSError("no such user") + + monkeypatch.setattr(sensor_log.getpass, "getuser", no_user) + data = json.loads(sensor_log.JsonRecordFormatter(include_identity=True).format(_record())) + assert data["username"] is None + + +def test_cli_log_identity_adds_username_and_hostname(tmp_path, monkeypatch): + monkeypatch.setattr(sensor_log.getpass, "getuser", lambda: "synthetic-user") + monkeypatch.setattr(sensor_log.socket, "gethostname", lambda: "synthetic-host") + _run_cli(tmp_path, monkeypatch, "--log-file", "--log-identity") + record = _lines(tmp_path / "sensor_runtime_errors.jsonl")[0] + assert (record["username"], record["hostname"]) == ("synthetic-user", "synthetic-host") + + +def test_cli_log_identity_requires_log_file(monkeypatch): + monkeypatch.setattr("sys.argv", ["adr-sensor", "--log-identity"]) + with pytest.raises(SystemExit) as error: + main() + assert error.value.code == 2