Adopt the relay logging standard

Sources/macMCP/LogLine.swift

@@ -0,0 +1,128 @@
+import Foundation
+import Security
+
+/// Structured stderr logging (stdout is the MCP protocol and is never written here).
+/// Every line carries the nine keys of relay's logging schema.
+enum LogLevel: String {
+    case error, warn, info, debug
+
+    var rank: Int {
+        switch self {
+        case .error: return 0
+        case .warn: return 1
+        case .info: return 2
+        case .debug: return 3
+        }
+    }
+}
+
+enum TraceID {
+    static func make() -> String {
+        var bytes = [UInt8](repeating: 0, count: 16)
+        if SecRandomCopyBytes(kSecRandomDefault, bytes.count, &bytes) != errSecSuccess {
+            for i in bytes.indices { bytes[i] = UInt8.random(in: 0...255) }
+        }
+        return bytes.map { String(format: "%02x", $0) }.joined()
+    }
+
+    /// Returns `raw` when it is 8-64 of [A-Za-z0-9_-], else a fresh ID.
+    /// The rejected value is never logged.
+    static func accept(_ raw: String?) -> String {
+        guard let raw, (8...64).contains(raw.utf8.count),
+              raw.utf8.allSatisfy({ c in
+                  (c >= 0x30 && c <= 0x39) || (c >= 0x41 && c <= 0x5A)
+                      || (c >= 0x61 && c <= 0x7A) || c == 0x5F || c == 0x2D
+              })
+        else { return make() }
+        return raw
+    }
+}
+
+final class StructuredLog {
+    private static let maxText = 500
+    private static let debugWindow: TimeInterval = 30 * 60
+    private static let reserved: Set<String> = [
+        "ts", "level", "msg", "service", "op", "status", "duration_ms", "error", "trace_id",
+    ]
+
+    private let service: String
+    private let now: () -> Date
+    private let sink: (String) -> Void
+    private let lock = NSLock()
+    private var level: LogLevel
+    private let debugDeadline: Date?
+
+    init(service: String, levelSetting: String?, now: @escaping () -> Date = Date.init,
+         sink: @escaping (String) -> Void) {
+        self.service = service
+        self.now = now
+        self.sink = sink
+        let parsed = levelSetting.flatMap { LogLevel(rawValue: $0.lowercased()) } ?? .info
+        self.level = parsed
+        self.debugDeadline = parsed == .debug ? now().addingTimeInterval(Self.debugWindow) : nil
+    }
+
+    static let shared: StructuredLog = {
+        let env = ProcessInfo.processInfo.environment
+        let id = env["RELAY_SERVICE_ID"] ?? ""
+        return StructuredLog(
+            service: id.isEmpty ? "macmcp" : id,
+            levelSetting: env["RELAY_LOG_LEVEL"],
+            sink: { line in
+                if let data = (line + "\n").data(using: .utf8) {
+                    FileHandle.standardError.write(data)
+                }
+            })
+    }()
+
+    func log(_ level: LogLevel, _ msg: String, op: String? = nil, status: String? = nil,
+             durationMs: Int? = nil, error: String? = nil, traceId: String? = nil,
+             attrs: [String: String] = [:]) {
+        lock.lock()
+        defer { lock.unlock() }
+        if let deadline = debugDeadline, self.level == .debug, now() >= deadline {
+            self.level = .info
+            emit(.warn, "debug logging ended after 30 minutes; level is now info",
+                 op: "log", status: "error", durationMs: 0, error: "debug_window_expired", traceId: "", attrs: [:])
+        }
+        guard level.rank <= self.level.rank else { return }
+        emit(level, msg, op: op ?? "log",
+             status: status ?? ((level == .error || level == .warn) ? "error" : "ok"),
+             durationMs: durationMs ?? 0, error: error ?? "", traceId: traceId ?? "", attrs: attrs)
+    }
+
+    private func emit(_ level: LogLevel, _ msg: String, op: String, status: String,
+                      durationMs: Int, error: String, traceId: String, attrs: [String: String]) {
+        var obj: [String: Any] = [:]
+        for (k, v) in attrs {
+            obj[Self.reserved.contains(k) ? "attr_" + k : k] = v
+        }
+        obj["ts"] = Self.timestamp(now())
+        obj["level"] = level.rawValue
+        obj["msg"] = Self.truncate(msg)
+        obj["service"] = service
+        obj["op"] = op
+        obj["status"] = status
+        obj["duration_ms"] = NSNumber(value: durationMs)
+        obj["error"] = Self.truncate(error)
+        obj["trace_id"] = traceId
+        guard let data = try? JSONSerialization.data(withJSONObject: obj, options: [.sortedKeys]),
+              let line = String(data: data, encoding: .utf8) else { return }
+        sink(line)
+    }
+
+    private static func truncate(_ s: String) -> String {
+        let scalars = s.unicodeScalars
+        guard scalars.count > maxText else { return s }
+        var out = String.UnicodeScalarView()
+        out.append(contentsOf: scalars.prefix(maxText))
+        return String(out)
+    }
+
+    private static func timestamp(_ d: Date) -> String {
+        let f = ISO8601DateFormatter()
+        f.timeZone = TimeZone(identifier: "UTC")
+        f.formatOptions = [.withInternetDateTime, .withFractionalSeconds]
+        return f.string(from: d)
+    }
+}

Sources/macMCP/main.swift

@@ -157,7 +157,20 @@ while let line = readLine(strippingNewline: true) {
             }
             meta = object
         }
+        // Only the correlation ID is read from `_meta`; no argument or result
+        // text is ever logged, and nothing is added to the result's `_meta`.
+        let traceId = TraceID.accept(req.params?["_meta"]?.objectValue?["trace_id"]?.stringValue)
+        let callStart = Date()
         let result = registry.call(name: name, arguments: arguments, meta: meta)
+        let elapsedMs = max(0, Int(Date().timeIntervalSince(callStart) * 1000))
+        let denied = result.meta?["scope_violation"] == .bool(true)
+        let failed = result.isError == true
+        StructuredLog.shared.log(
+            (denied || failed) ? .warn : .info, "tool call", op: "tool.call",
+            status: denied ? "denied" : (failed ? "error" : "ok"),
+            durationMs: elapsedMs,
+            error: (denied || failed) ? "tool returned an error" : nil,
+            traceId: traceId, attrs: ["tool": String(name.unicodeScalars.prefix(500).map(Character.init))])
 
         let contentValues: [JSONValue] = result.content.map { c in
             .object(["type": .string(c.type), "text": .string(c.text)])

Tests/Fixtures/logging-schema.json

@@ -0,0 +1,35 @@
+{
+  "$schema": "https://json-schema.org/draft/2020-12/schema",
+  "$id": "relay-log-line",
+  "title": "Relay service log line",
+  "description": "One JSON object per line on stderr. See logging-standard.md. Lines that do not start with '{' (panics, third-party output) are allowed and are not validated.",
+  "type": "object",
+  "required": ["ts", "level", "msg", "service", "op", "status", "duration_ms", "error", "trace_id"],
+  "properties": {
+    "ts": {
+      "description": "UTC, RFC 3339, millisecond precision.",
+      "type": "string",
+      "pattern": "^\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}\\.\\d{3}Z$"
+    },
+    "level": { "enum": ["error", "warn", "info", "debug"] },
+    "msg": { "type": "string", "maxLength": 500 },
+    "service": { "type": "string", "minLength": 1 },
+    "op": {
+      "description": "Dotted operation name, for example schedule.create or job.fire.",
+      "type": "string",
+      "pattern": "^[a-z][a-z0-9_]*(\\.[a-z][a-z0-9_]*)*$"
+    },
+    "status": { "enum": ["ok", "error", "denied"] },
+    "duration_ms": { "description": "0 for a line that marks a point in time.", "type": "integer", "minimum": 0 },
+    "error": { "description": "Empty string when status is ok. Names the failure; never carries a body or credential.", "type": "string", "maxLength": 500 },
+    "trace_id": {
+      "description": "Empty string outside any user action, such as startup or a background tick.",
+      "type": "string",
+      "pattern": "^$|^[A-Za-z0-9_-]{8,64}$"
+    },
+    "session_id": { "type": "string", "minLength": 1 },
+    "job_id": { "type": "string", "minLength": 1 },
+    "run_id": { "type": "string", "minLength": 1 }
+  },
+  "additionalProperties": true
+}