Strip credentials from every emitted log line

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 `<private>`.
     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)")

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 = "<redacted>"
+
+    /// 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<Int>? {
+        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
+    }
+}

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=<redacted>"))
+        #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)=<redacted>&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="<redacted>""#))
+        #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: <redacted> 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=<redacted>; 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=<redacted>"))
+    }
+
+    /// 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=<redacted>&b=2&access_token=<redacted>&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=<redacted>") == 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
+        }
+    }
+}