From 085bd48e15003ec4ca56d296552ff23405033715 Mon Sep 17 00:00:00 2001 From: Vincent Herbst Date: Wed, 26 Aug 2026 15:47:40 +0200 Subject: [PATCH] fix(diagnostics): strip credentials from every emitted log line MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit EngineLog logs whole URLs on purpose: host, path and query are what a playback report is diagnosed from. Media servers routinely put the access token in that same query, Jellyfin's `api_key=` being the case at hand, so `[AetherEngine] load url=`, `[NativeAVPlayerHost] load url=` and `asset.url=` carried a live credential into every sink at once. Emission is `.public` privacy, so a Console.app capture or a sysdiagnose held it in clear text, and the host handler passed it to whatever in-app log a consumer built on it. That makes it the engine's problem rather than each consumer's: the engine composes the line, it reaches three sinks a consumer does not control, and a host-side scrub only ever covers the one sink that host owns. Sodalite had just turned its diagnostic log on for App Store users so reporters can hand logs over, which is exactly the situation where this ships a token. Both public emit overloads now funnel through one private deliver(), which runs the line through LogRedaction first. Redacting at the funnel rather than at the call sites is the point: a URL logged by code added later is covered without its author knowing the redactor exists. Covered names are generic rather than Jellyfin-specific: api_key, apikey, access_token, token, secret, password, signature, x-emby-token, x-mediabrowser-token, connect.sid, in the query form, both header forms and the cookie form. Values go whole, never as a prefix. Public API is unchanged and the redactor is internal, so docs/api.md needs no entry. The redactor works on UTF-8 bytes and allocates its output only once something matches. That is not premature. The first version compared Characters and built a lowercased String per position, which cost enough on this path to shift request timing in ServedFromMemoryProgressTests: emit is called from the demuxer and the segment producer, so anything per-line here is per-line everywhere. That test is what caught it, and it passes again. 11 tests cover the forms, the boundary rule that keeps `hasToken=true` and `[SWDiag] enq=…` intact, and that the host handler never sees the raw token. Full suite: 2125 tests in 299 suites pass. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01RbWZLwBVLGM1xUVXa9NeJ1 --- .../AetherEngine/Diagnostics/EngineLog.swift | 13 +- .../Diagnostics/LogRedaction.swift | 139 +++++++++++++++++ .../AetherEngineTests/LogRedactionTests.swift | 142 ++++++++++++++++++ 3 files changed, 292 insertions(+), 2 deletions(-) create mode 100644 Sources/AetherEngine/Diagnostics/LogRedaction.swift create mode 100644 Tests/AetherEngineTests/LogRedactionTests.swift 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 + } + } +}