diff --git a/Sources/AetherEngine/Diagnostics/EngineLog.swift b/Sources/AetherEngine/Diagnostics/EngineLog.swift index 4cabc9cb..2d39341f 100644 --- a/Sources/AetherEngine/Diagnostics/EngineLog.swift +++ b/Sources/AetherEngine/Diagnostics/EngineLog.swift @@ -53,11 +53,20 @@ public enum EngineLog { /// Emit under a specific category. `.public` privacy so Console shows the full string instead of ``. public static func emit(_ line: String, category: Category) { - loggers[category]?.log("\(line, privacy: .public)") - handler?(line) + deliver(line, category: category, level: .info) } public static func emit(_ line: String, category: Category, level: Level) { + deliver(line, category: category, level: level) + } + + /// The single funnel every line passes, which is where credentials come out (see LogRedaction). + /// Doing it here rather than at the call sites is what makes a URL logged by code added later safe + /// without its author knowing the redactor exists, and it covers OSLog as well as the host handler: + /// `.public` privacy means a Console.app capture or a sysdiagnose would otherwise carry the token + /// in clear text even for a host that scrubs its own log. + private static func deliver(_ line: String, category: Category, level: Level) { + let line = LogRedaction.redact(line) switch level { case .info: loggers[category]?.log("\(line, privacy: .public)") diff --git a/Sources/AetherEngine/Diagnostics/LogRedaction.swift b/Sources/AetherEngine/Diagnostics/LogRedaction.swift new file mode 100644 index 00000000..b188ad3c --- /dev/null +++ b/Sources/AetherEngine/Diagnostics/LogRedaction.swift @@ -0,0 +1,139 @@ +import Foundation + +/// Strips credentials out of a diagnostic line before `EngineLog` emits it. +/// +/// The engine logs whole URLs on purpose (`[AetherEngine] load url=`, `[NativeAVPlayerHost] load +/// url=`, `asset.url=`): host, path and query are what a playback report is diagnosed from. But media +/// servers routinely put the access token in that query, Jellyfin's `api_key=` being the case this was +/// written for, so those lines carry a live credential into `os.Logger` (a Console.app capture, a +/// sysdiagnose) and into whatever handler the host installed for its own in-app log. +/// +/// That makes it the engine's problem rather than each host's: the engine composes the line, it reaches +/// three sinks a host does not control, and a host-side scrub only ever covers the one sink it owns. +/// +/// Redacts at the `EngineLog` funnel, never at the call sites, so a URL logged by code added later is +/// covered without its author knowing this type exists. Over-redaction is the safe failure here; +/// under-redaction ships a credential. The value goes whole rather than truncated to a prefix: a prefix +/// still narrows a brute-force and answers no question a playback bug asks. +enum LogRedaction { + + static let placeholder = "" + + /// Generic credential parameter and header names; the engine is not tied to one server product. + /// Held as lowercase ASCII bytes and matched longest first, so `x-mediabrowser-token` wins over its + /// `token` suffix. `token` alone is deliberately broad and only fires on a boundary, so identifiers + /// such as `hasToken` and `refreshTokenAt` are left alone. + private static let keys: [[UInt8]] = [ + "x-mediabrowser-token", "x-emby-token", "access_token", "accesstoken", "connect.sid", + "signature", "password", "api_key", "apikey", "secret", "token", + ].map { Array($0.utf8) } + + private static let placeholderBytes = Array(placeholder.utf8) + + /// Works on UTF-8 bytes, not Characters, and allocates the output only once something actually + /// matches. That is not premature: a Character-level pass building a lowercased String per position + /// cost enough on this hot path to shift the request timing in `ServedFromMemoryProgressTests`, + /// which is how the first version of this file was caught. `emit` is called from the demuxer and the + /// segment producer, so anything per-line here is per-line everywhere. + static func redact(_ line: String) -> String { + let bytes = Array(line.utf8) + var out: [UInt8]? + var copiedUpTo = 0 + var i = 0 + + while i < bytes.count { + guard let keyLength = matchedKeyLength(in: bytes, at: i), + let value = valueRange(in: bytes, after: i + keyLength) else { + i += 1 + continue + } + if out == nil { + out = [] + out?.reserveCapacity(bytes.count) + } + out?.append(contentsOf: bytes[copiedUpTo ..< value.lowerBound]) + out?.append(contentsOf: placeholderBytes) + copiedUpTo = value.upperBound + i = value.upperBound + } + + guard var out else { return line } + out.append(contentsOf: bytes[copiedUpTo...]) + return String(decoding: out, as: UTF8.self) + } + + /// Length of the key starting here, or nil. The key must start on a boundary, else `token` would + /// fire inside `hasToken`. A separator such as the `-` in `X-Emby-Token` or the `_` in `api_key` is + /// a boundary; an ASCII letter or digit is not. + private static func matchedKeyLength(in bytes: [UInt8], at index: Int) -> Int? { + if index > 0, isLetterOrDigit(bytes[index - 1]) { return nil } + for key in keys where index + key.count <= bytes.count { + var matched = true + for offset in 0 ..< key.count where lowercased(bytes[index + offset]) != key[offset] { + matched = false + break + } + if matched { return key.count } + } + return nil + } + + /// The span holding the secret, given the index just past the key. Covers the query form + /// (`api_key=abc&next=1`), both header forms (`Token="abc"`, `X-Emby-Token: abc`) and the cookie + /// form (`connect.sid=abc; Path=/`). Nil when there is no assignment or the value is empty, so + /// `api_key=` and a bare mention in prose are left alone. + private static func valueRange(in bytes: [UInt8], after keyEnd: Int) -> Range? { + var i = keyEnd + while i < bytes.count, bytes[i] == UInt8(ascii: " ") { i += 1 } + guard i < bytes.count, bytes[i] == UInt8(ascii: "=") || bytes[i] == UInt8(ascii: ":") else { + return nil + } + let isHeaderSeparator = bytes[i] == UInt8(ascii: ":") + i += 1 + + // Only a header separator may be followed by spaces. After `=` the value starts immediately: + // a URL query and a cookie never space it out, and skipping here would let prose such as + // "api_key= (missing)" read as a credential and swallow the rest of the line. + var afterSpaces = i + while afterSpaces < bytes.count, bytes[afterSpaces] == UInt8(ascii: " ") { afterSpaces += 1 } + var quote: UInt8? + if afterSpaces < bytes.count, + bytes[afterSpaces] == UInt8(ascii: "\"") || bytes[afterSpaces] == UInt8(ascii: "'") { + quote = bytes[afterSpaces] + i = afterSpaces + 1 + } else if isHeaderSeparator { + i = afterSpaces + } + let start = i + + if let quote { + while i < bytes.count, bytes[i] != quote { i += 1 } + } else { + while i < bytes.count, !isValueTerminator(bytes[i]) { i += 1 } + } + return start < i ? start ..< i : nil + } + + /// `:` counts, so `…&api_key=abc: timeout` gives the token back and keeps the error text. None of + /// the credential shapes here (hex, base64url, percent-encoded cookie) contain a literal colon. + private static func isValueTerminator(_ b: UInt8) -> Bool { + switch b { + case UInt8(ascii: "&"), UInt8(ascii: ";"), UInt8(ascii: ","), UInt8(ascii: ")"), + UInt8(ascii: ">"), UInt8(ascii: ":"), UInt8(ascii: "\""), UInt8(ascii: "'"), + UInt8(ascii: " "), 0x09, 0x0A, 0x0D: + return true + default: + return false + } + } + + private static func isLetterOrDigit(_ b: UInt8) -> Bool { + (b >= UInt8(ascii: "a") && b <= UInt8(ascii: "z")) + || (b >= UInt8(ascii: "A") && b <= UInt8(ascii: "Z")) + || (b >= UInt8(ascii: "0") && b <= UInt8(ascii: "9")) + } + + private static func lowercased(_ b: UInt8) -> UInt8 { + (b >= UInt8(ascii: "A") && b <= UInt8(ascii: "Z")) ? b + 32 : b + } +} diff --git a/Tests/AetherEngineTests/LogRedactionTests.swift b/Tests/AetherEngineTests/LogRedactionTests.swift new file mode 100644 index 00000000..44260440 --- /dev/null +++ b/Tests/AetherEngineTests/LogRedactionTests.swift @@ -0,0 +1,142 @@ +import Foundation +import Testing +@testable import AetherEngine + +/// The engine logs whole URLs so a report can be diagnosed from host, path and query. Media servers put +/// the access token in that same query, and `EngineLog` emits with `.public` privacy into OSLog plus +/// whatever handler the host installed, so an unredacted line is a live credential in a Console.app +/// capture, a sysdiagnose, and every in-app log a host builds on the handler. +/// Serialized: `EngineLog.handler` is process-global, so two of these running at once would +/// each install over the other and read an empty capture. +@Suite("EngineLog credential stripping", .serialized) +struct LogRedactionTests { + + private let token = "9f2c1ab34de5470fa1b6c8d90e7f2a11" + + @Test("a media-server stream URL loses its api_key and keeps what diagnoses the report") + func streamURLQuery() { + let line = LogRedaction.redact( + "[AetherEngine] load url=https://media.example.org/Videos/abc123/stream.mkv" + + "?api_key=\(token)&Static=true&MediaSourceId=abc123 source-format=mkv" + ) + #expect(!line.contains(token)) + #expect(line.contains("api_key=")) + #expect(line.contains("media.example.org/Videos/abc123/stream.mkv")) + #expect(line.contains("Static=true")) + #expect(line.contains("MediaSourceId=abc123")) + #expect(line.hasSuffix("source-format=mkv")) + } + + @Test("the generic credential parameter names are covered", arguments: [ + "api_key", "ApiKey", "access_token", "token", "password", "secret", "signature", + "X-Emby-Token", "X-MediaBrowser-Token", + ]) + func genericKeyNames(key: String) { + let line = LogRedaction.redact("[x] https://s/a?\(key)=\(token)&keep=1") + #expect(!line.contains(token)) + #expect(line == "[x] https://s/a?\(key)=&keep=1") + } + + @Test("the quoted header form is stripped inside its quotes") + func quotedHeaderForm() { + let line = LogRedaction.redact(#"Authorization: MediaBrowser Client="Host", Token="\#(token)", Device="TV""#) + #expect(!line.contains(token)) + #expect(line.contains(#"Token="""#)) + #expect(line.contains(#"Client="Host""#)) + #expect(line.contains(#"Device="TV""#)) + } + + @Test("the colon-separated header form is stripped") + func colonSeparatedHeader() { + let line = LogRedaction.redact("[http] X-Emby-Token: \(token) sent") + #expect(line == "[http] X-Emby-Token: sent") + } + + @Test("a session cookie is stripped up to the attribute separator") + func cookieForm() { + let line = LogRedaction.redact("[net] connect.sid=s%3Aabc.def+ghi; Path=/; HttpOnly") + #expect(!line.contains("s%3Aabc.def")) + #expect(line == "[net] connect.sid=; Path=/; HttpOnly") + } + + @Test("a colon after the value ends it, so the error text survives") + func colonTerminatesTheValue() { + let line = LogRedaction.redact("[Image] fetch failed https://s/i?ApiKey=\(token): timeout") + #expect(line.hasSuffix(": timeout")) + #expect(line.contains("ApiKey=")) + } + + /// The broad `token` and `secret` keys must not fire mid-identifier, or the per-second counters the + /// engine exists to report start reading as redactions. + @Test("a key substring inside another identifier is left alone", arguments: [ + "[session] hasToken=true refreshTokenAt=120s", + "[SWDiag] enq=48 layerDrop=0 delay=0.02 cushion=1.8", + "[LiveDirect] eligible: route=hls tuner=file", + "[HLSVideoEngine] serving on http://127.0.0.1:52341/master.m3u8 (dvModeAvailable=true)", + "[DisplayCriteria] refreshRate=23.976 videoRange=HLG", + ]) + func doesNotFireMidIdentifier(line: String) { + #expect(LogRedaction.redact(line) == line) + } + + @Test("an empty value and a bare mention are left alone") + func nothingToStrip() { + #expect(LogRedaction.redact("[auth] api_key= (missing)") == "[auth] api_key= (missing)") + #expect(LogRedaction.redact("no token was supplied") == "no token was supplied") + } + + @Test("several credentials in one line are all stripped") + func multiplePerLine() { + let line = LogRedaction.redact("a=1&api_key=\(token)&b=2&access_token=\(token)&c=3") + #expect(!line.contains(token)) + #expect(line == "a=1&api_key=&b=2&access_token=&c=3") + } + + /// The point of putting this in EngineLog rather than in each host: the handler a host installs + /// must never see the raw token, whether or not that host scrubs its own log. + @Test("the host handler receives the redacted line") + func handlerSeesRedactedLine() { + let box = LineBox() + let previous = EngineLog.handler + EngineLog.handler = { box.append($0) } + defer { EngineLog.handler = previous } + + EngineLog.emit("[test] load url=https://s/v?api_key=\(token)&Static=true", category: .engine) + + let captured = box.lines + #expect(captured.count == 1) + #expect(captured.first?.contains("api_key=") == true) + #expect(captured.first?.contains(token) == false) + #expect(captured.first?.contains("Static=true") == true) + } + + /// `.verbose` never reaches the handler; it still goes to OSLog, which is why redaction sits on the + /// shared funnel and not on the `.info` branch alone. + @Test("a verbose line is withheld from the handler") + func verboseSkipsTheHandler() { + let box = LineBox() + let previous = EngineLog.handler + EngineLog.handler = { box.append($0) } + defer { EngineLog.handler = previous } + + EngineLog.emit("[test] per-segment trace api_key=\(token)", category: .session, level: .verbose) + + #expect(box.lines.isEmpty) + } + + /// The handler is called on whatever thread emitted, so the capture needs its own lock. + private final class LineBox: @unchecked Sendable { + private let lock = NSLock() + private var storage: [String] = [] + + func append(_ line: String) { + lock.lock(); defer { lock.unlock() } + storage.append(line) + } + + var lines: [String] { + lock.lock(); defer { lock.unlock() } + return storage + } + } +}