diff --git a/Sources/macMCP/LogLine.swift b/Sources/macMCP/LogLine.swift new file mode 100644 index 0000000..6a66334 --- /dev/null +++ b/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 = [ + "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) + } +} diff --git a/Sources/macMCP/main.swift b/Sources/macMCP/main.swift index 385dffa..fa46af5 100644 --- a/Sources/macMCP/main.swift +++ b/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)]) diff --git a/Tests/Fixtures/logging-schema.json b/Tests/Fixtures/logging-schema.json new file mode 100644 index 0000000..7f4f50b --- /dev/null +++ b/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 +} diff --git a/Tests/macMCPTests/LogLineTests.swift b/Tests/macMCPTests/LogLineTests.swift new file mode 100644 index 0000000..6dc7ada --- /dev/null +++ b/Tests/macMCPTests/LogLineTests.swift @@ -0,0 +1,334 @@ +import XCTest +import Foundation +@testable import macmcp + +// MARK: - Test-local JSON Schema checker (exactly the keywords the schema uses) + +private enum MiniSchema { + static let ignored: Set = ["$schema", "$id", "title", "description"] + static let supported: Set = [ + "type", "required", "enum", "pattern", "maxLength", "minLength", + "minimum", "additionalProperties", "properties", + ] + + static func load() throws -> [String: Any] { + let url = URL(fileURLWithPath: #filePath) + .deletingLastPathComponent() + .appendingPathComponent("../Fixtures/logging-schema.json") + let obj = try JSONSerialization.jsonObject(with: Data(contentsOf: url)) + return try XCTUnwrap(obj as? [String: Any]) + } + + private static func isBool(_ v: Any) -> Bool { + guard let n = v as? NSNumber else { return false } + return CFGetTypeID(n) == CFBooleanGetTypeID() + } + + static func validate(_ value: Any, _ schema: [String: Any], at path: String = "$") -> [String] { + var errs: [String] = [] + for key in schema.keys where !ignored.contains(key) && !supported.contains(key) { + errs.append("\(path): unsupported schema keyword \(key)") + } + if let t = schema["type"] as? String { + switch t { + case "object": if !(value is [String: Any]) { errs.append("\(path): not object") } + case "string": if !(value is String) { errs.append("\(path): not string") } + case "integer": + if isBool(value) || !(value is NSNumber) || (value as! NSNumber).doubleValue.rounded() != (value as! NSNumber).doubleValue { + errs.append("\(path): not integer") + } + default: errs.append("\(path): unsupported type \(t)") + } + } + if let e = schema["enum"] as? [String] { + if let s = value as? String { if !e.contains(s) { errs.append("\(path): \(s) not in enum") } } + else { errs.append("\(path): enum on non-string") } + } + if let s = value as? String { + if let p = schema["pattern"] as? String { + let re = try? NSRegularExpression(pattern: p) + if re?.firstMatch(in: s, range: NSRange(s.startIndex..., in: s)) == nil { + errs.append("\(path): \(s) fails pattern \(p)") + } + } + if let m = schema["maxLength"] as? Int, s.count > m { errs.append("\(path): too long") } + if let m = schema["minLength"] as? Int, s.count < m { errs.append("\(path): too short") } + } + if let m = schema["minimum"] as? Double, let n = value as? NSNumber, n.doubleValue < m { + errs.append("\(path): below minimum") + } + if let obj = value as? [String: Any] { + for r in schema["required"] as? [String] ?? [] where obj[r] == nil { + errs.append("\(path): missing \(r)") + } + let props = schema["properties"] as? [String: Any] ?? [:] + for (k, sub) in props { + if let v = obj[k], let subSchema = sub as? [String: Any] { + errs += validate(v, subSchema, at: "\(path).\(k)") + } + } + if let ap = schema["additionalProperties"] as? Bool, !ap { + for k in obj.keys where props[k] == nil { errs.append("\(path): extra \(k)") } + } + } + return errs + } +} + +// MARK: - Helpers + +private let nineKeys = ["ts", "level", "msg", "service", "op", "status", "duration_ms", "error", "trace_id"] + +private final class Capture { + var lines: [String] = [] + var sink: (String) -> Void { { [self] in lines.append($0.trimmingCharacters(in: .whitespacesAndNewlines)) } } + func objects() throws -> [[String: Any]] { + try lines.map { try XCTUnwrap(JSONSerialization.jsonObject(with: Data($0.utf8)) as? [String: Any]) } + } +} + +private func makeLog(_ cap: Capture, level: String? = nil, now: @escaping () -> Date = { Date(timeIntervalSince1970: 1_700_000_000) }) -> StructuredLog { + StructuredLog(service: "macmcp-test", levelSetting: level, now: now, sink: cap.sink) +} + +final class LogLineTests: XCTestCase { + + // MARK: Unit + + func testEveryLevelWithEntityAttrsValidatesAgainstSchema() throws { + let schema = try MiniSchema.load() + let cap = Capture() + let log = makeLog(cap, level: "debug") + for lvl in [LogLevel.error, .warn, .info, .debug] { + log.log(lvl, "plain \(lvl.rawValue)") + log.log(lvl, "full", op: "tool.call", status: "ok", durationMs: 12, error: "", traceId: "abcdef1234567890", + attrs: ["session_id": "s1", "job_id": "j1", "run_id": "r1", "tool": "acme_tool"]) + } + let objs = try cap.objects() + XCTAssertEqual(objs.count, 8) + for o in objs { + XCTAssertEqual(MiniSchema.validate(o, schema), [], "\(o)") + for k in nineKeys { XCTAssertNotNil(o[k], "missing \(k)") } + } + } + + func testCheckerRejectsUnknownKeywordAndBadLine() throws { + XCTAssertFalse(MiniSchema.validate(["a": 1], ["type": "object", "oneOf": []]).isEmpty) + XCTAssertFalse(MiniSchema.validate(["ts": "x"], try MiniSchema.load()).isEmpty) + } + + func testDefaults() throws { + let cap = Capture() + let log = makeLog(cap, level: "info") + log.log(.error, "e"); log.log(.warn, "w"); log.log(.info, "i") + let o = try cap.objects() + XCTAssertEqual(o.map { $0["status"] as? String }, ["error", "error", "ok"]) + for x in o { + XCTAssertEqual(x["op"] as? String, "log") + XCTAssertEqual(x["duration_ms"] as? Int, 0) + XCTAssertEqual(x["error"] as? String, "") + XCTAssertEqual(x["trace_id"] as? String, "") + XCTAssertEqual(x["service"] as? String, "macmcp-test") + } + XCTAssertEqual(o[0]["level"] as? String, "error") + } + + func testMsgAndErrorTruncateAt500() throws { + let cap = Capture() + makeLog(cap).log(.info, String(repeating: "m", count: 900), error: String(repeating: "e", count: 900)) + let o = try XCTUnwrap(cap.objects().first) + XCTAssertEqual((o["msg"] as? String)?.count, 500) + XCTAssertEqual((o["error"] as? String)?.count, 500) + } + + func testTruncationCountsUnicodeScalarsNotGraphemes() throws { + // 1 base + 600 combining marks compose a single grapheme but 601 scalars. + let s = "e" + String(repeating: "\u{0301}", count: 600) + let cap = Capture() + makeLog(cap).log(.info, s, error: s) + let o = try XCTUnwrap(cap.objects().first) + XCTAssertEqual((o["msg"] as? String)?.unicodeScalars.count, 500) + XCTAssertEqual((o["error"] as? String)?.unicodeScalars.count, 500) + } + + func testReservedAttrsAreRenamed() throws { + let cap = Capture() + makeLog(cap).log(.info, "real", traceId: "abcdef1234567890", + attrs: ["ts": "A", "level": "B", "msg": "C", "service": "D", "trace_id": "E", "tool": "T"]) + let o = try XCTUnwrap(cap.objects().first) + XCTAssertEqual(o["msg"] as? String, "real") + XCTAssertEqual(o["service"] as? String, "macmcp-test") + XCTAssertEqual(o["level"] as? String, "info") + XCTAssertEqual(o["trace_id"] as? String, "abcdef1234567890") + XCTAssertNotEqual(o["ts"] as? String, "A") + for (k, v) in ["ts": "A", "level": "B", "msg": "C", "service": "D", "trace_id": "E"] { + XCTAssertEqual(o["attr_\(k)"] as? String, v) + } + XCTAssertEqual(o["tool"] as? String, "T") + } + + func testLevelSettingFiltering() { + for setting in [nil, "", "verbose", "DEBUGGY"] as [String?] { + let cap = Capture() + let log = makeLog(cap, level: setting) + log.log(.debug, "d"); log.log(.info, "i") + XCTAssertEqual(cap.lines.count, 1, "setting \(String(describing: setting))") + } + let cap = Capture() + let log = makeLog(cap, level: "error") + log.log(.warn, "w"); log.log(.info, "i"); log.log(.error, "e") + XCTAssertEqual(cap.lines.count, 1) + } + + func testDebugExpiresAfterThirtyMinutesWithOneWarn() throws { + var t = Date(timeIntervalSince1970: 1_700_000_000) + let cap = Capture() + let log = makeLog(cap, level: "debug", now: { t }) + log.log(.debug, "early") + t += 29 * 60 + log.log(.debug, "still on") + XCTAssertEqual(cap.lines.count, 2) + t += 2 * 60 + log.log(.info, "after") + log.log(.debug, "dropped") + log.log(.info, "again") + let o = try cap.objects() + XCTAssertEqual(o.map { $0["msg"] as? String }.count, 5) + XCTAssertEqual(o[2]["level"] as? String, "warn") + XCTAssertEqual(o[2]["error"] as? String, "debug_window_expired") + XCTAssertEqual(o[3]["msg"] as? String, "after") + XCTAssertEqual(o[4]["msg"] as? String, "again") + XCTAssertEqual(o.filter { $0["level"] as? String == "warn" }.count, 1) + XCTAssertEqual(MiniSchema.validate(o[2], try MiniSchema.load()), []) + } + + func testTraceIDs() { + let id = TraceID.make() + XCTAssertNotNil(id.range(of: "^[0-9a-f]{32}$", options: .regularExpression)) + XCTAssertNotEqual(id, TraceID.make()) + XCTAssertEqual(TraceID.accept("abcdef1234567890"), "abcdef1234567890") + XCTAssertEqual(TraceID.accept("a_b-c_d-1"), "a_b-c_d-1") + let max = String(repeating: "a", count: 64) + XCTAssertEqual(TraceID.accept(max), max) + for bad in [nil, "", "short", "bad id!", String(repeating: "a", count: 65), "abcdef12\n"] as [String?] { + let out = TraceID.accept(bad) + XCTAssertNotEqual(out, bad) + XCTAssertNotNil(out.range(of: "^[0-9a-f]{32}$", options: .regularExpression)) + } + } + + // MARK: Process level + + private func executableURL() throws -> URL { + let bundle = Bundle.allBundles.first { $0.bundleURL.pathExtension == "xctest" } + let dir = try XCTUnwrap(bundle?.bundleURL.deletingLastPathComponent()) + let exe = dir.appendingPathComponent("macmcp") + guard FileManager.default.isExecutableFile(atPath: exe.path) else { + XCTFail("macmcp executable not found next to the xctest bundle at \(exe.path); run `swift build` first") + throw CocoaError(.fileNoSuchFile) + } + return exe + } + + private func run(meta: String?, tool: String = "no_such_tool", env extra: [String: String] = [:]) throws -> (out: String, err: String) { + let exe = try executableURL() + let metaPart = meta.map { ",\"_meta\":\($0)" } ?? "" + let req = "{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"tools/call\",\"params\":{\"name\":\"\(tool)\",\"arguments\":{\"secret\":\"CANARY-TOKEN-7731\"}\(metaPart)}}\n" + let p = Process() + p.executableURL = exe + var env = ProcessInfo.processInfo.environment + env.removeValue(forKey: "RELAY_LOG_LEVEL") + env.removeValue(forKey: "RELAY_SERVICE_ID") + for (k, v) in extra { env[k] = v } + p.environment = env + let inP = Pipe(), outP = Pipe(), errP = Pipe() + p.standardInput = inP; p.standardOutput = outP; p.standardError = errP + var outData = Data(), errData = Data() + let group = DispatchGroup() + for (pipe, isOut) in [(outP, true), (errP, false)] { + group.enter() + DispatchQueue.global().async { + let d = pipe.fileHandleForReading.readDataToEndOfFile() + if isOut { outData = d } else { errData = d } + group.leave() + } + } + try p.run() + inP.fileHandleForWriting.write(Data(req.utf8)) + try inP.fileHandleForWriting.close() + if group.wait(timeout: .now() + 30) == .timedOut { p.terminate(); XCTFail("macmcp did not exit") } + p.waitUntilExit() + return (String(decoding: outData, as: UTF8.self), String(decoding: errData, as: UTF8.self)) + } + + private func jsonLines(_ s: String) -> [[String: Any]] { + s.split(separator: "\n").filter { $0.hasPrefix("{") }.compactMap { + try? JSONSerialization.jsonObject(with: Data($0.utf8)) as? [String: Any] + } + } + + private func toolCallLine(_ err: String) throws -> [String: Any] { + let schema = try MiniSchema.load() + let lines = jsonLines(err) + XCTAssertEqual(lines.count, err.split(separator: "\n").filter { $0.hasPrefix("{") }.count, "unparseable JSON line on stderr") + for l in lines { XCTAssertEqual(MiniSchema.validate(l, schema), [], "\(l)") } + return try XCTUnwrap(lines.first { $0["op"] as? String == "tool.call" }, "no tool.call line in: \(err)") + } + + func testStdoutCarriesOnlyTheResponseAndStderrCarriesTheSchemaLine() throws { + let (out, err) = try run(meta: nil) + let outLines = out.split(separator: "\n") + XCTAssertEqual(outLines.count, 1) + for l in outLines { + let o = try XCTUnwrap(JSONSerialization.jsonObject(with: Data(l.utf8)) as? [String: Any]) + XCTAssertNotNil(o["jsonrpc"]) + XCTAssertNil(o["ts"]); XCTAssertNil(o["service"]) + XCTAssertNil(o["_meta"]) + XCTAssertNil((o["result"] as? [String: Any])?["_meta"]) + } + let line = try toolCallLine(err) + XCTAssertEqual(line["status"] as? String, "error") + XCTAssertFalse(err.contains("CANARY-TOKEN-7731"), "arguments leaked into the log") + // absent _meta: an ID is created + XCTAssertNotNil((line["trace_id"] as? String)?.range(of: "^[0-9a-f]{32}$", options: .regularExpression)) + } + + func testInboundTraceIDIsKeptWhenValid() throws { + let (out, err) = try run(meta: "{\"trace_id\":\"abcdef1234567890\"}") + XCTAssertEqual(try toolCallLine(err)["trace_id"] as? String, "abcdef1234567890") + XCTAssertFalse(out.contains("trace_id"), "macMCP must add nothing to the response") + } + + func testInvalidInboundTraceIDIsReplacedAndNeverLogged() throws { + let (out, err) = try run(meta: "{\"trace_id\":\"bad id!\"}") + let id = try XCTUnwrap(try toolCallLine(err)["trace_id"] as? String) + XCTAssertNotNil(id.range(of: "^[0-9a-f]{32}$", options: .regularExpression)) + XCTAssertFalse(err.contains("bad id!")) + XCTAssertFalse(out.contains("trace_id")) + } + + func testUnknownToolResponseBytesAndWarnLine() throws { + let (out, err) = try run(meta: nil) + XCTAssertEqual(out, "{\"id\":1,\"jsonrpc\":\"2.0\",\"result\":{\"content\":[{\"text\":\"unknown tool: no_such_tool\",\"type\":\"text\"}],\"isError\":true}}\n") + let calls = jsonLines(err).filter { $0["op"] as? String == "tool.call" } + XCTAssertEqual(calls.count, 1) + XCTAssertEqual(calls[0]["level"] as? String, "warn") + XCTAssertEqual(calls[0]["status"] as? String, "error") + XCTAssertEqual(calls[0]["tool"] as? String, "no_such_tool") + } + + func testEnvLevelAndServiceIdReachTheLog() throws { + let (_, quiet) = try run(meta: nil, env: ["RELAY_LOG_LEVEL": "error", "RELAY_SERVICE_ID": "testsvc"]) + XCTAssertTrue(jsonLines(quiet).filter { $0["op"] as? String == "tool.call" }.isEmpty) + let (_, loud) = try run(meta: nil, env: ["RELAY_LOG_LEVEL": "warn", "RELAY_SERVICE_ID": "testsvc"]) + XCTAssertEqual(try toolCallLine(loud)["service"] as? String, "testsvc") + } + + func testScopeDeniedCallLogsWarnDenied() throws { + let (_, err) = try run(meta: "{\"project_id\":\"p\",\"trace_id\":\"abcdef1234567890\"}", tool: "mail_list_accounts") + let line = try toolCallLine(err) + XCTAssertEqual(line["level"] as? String, "warn") + XCTAssertEqual(line["status"] as? String, "denied") + XCTAssertEqual(line["trace_id"] as? String, "abcdef1234567890") + } +}