[AI-3363] Log the server's error code and bearer expiry on every 401

src/Capacitor.Cli.Core/Auth/JwtClaims.cs

@@ -2,13 +2,20 @@
 
 namespace Capacitor.Cli.Core.Auth;
 
-/// Reads one string claim out of a JWT payload WITHOUT validating the signature — the server
-/// validates via JWKS; a client only ever uses these values for display and row classification,
+/// Reads claims out of a JWT payload WITHOUT validating the signature — the server validates via
+/// JWKS; a client only ever uses these values for display, diagnostics and row classification,
 /// never for authorization.
 public static class JwtClaims {
-    public static string? TryGetString(string accessToken, string claimName) {
+    public static string? TryGetString(string accessToken, string claimName) =>
+        TryReadPayload(accessToken, root => root.Str(claimName));
+
+    /// <summary>A NumericDate claim (<c>exp</c>, <c>iat</c>), or null when absent or not a number.</summary>
+    public static DateTimeOffset? TryGetTime(string accessToken, string claimName) =>
+        TryReadPayload(accessToken, root => root.Num(claimName) is { } seconds ? DateTimeOffset.FromUnixTimeSeconds(seconds) : (DateTimeOffset?)null);
+
+    static T? TryReadPayload<T>(string accessToken, Func<JsonElement, T?> read) {
         var parts = accessToken.Split('.');
-        if (parts.Length < 2) return null;
+        if (parts.Length < 2) return default;
 
         try {
             var payload = parts[1].Replace('-', '+').Replace('_', '/');
@@ -19,9 +26,9 @@ public static class JwtClaims {
                 _ => payload,
             };
             using var doc = JsonDocument.Parse(Convert.FromBase64String(payload));
-            return doc.RootElement.Str(claimName);
-        } catch (Exception e) when (e is FormatException or JsonException) {
-            return null;
+            return read(doc.RootElement);
+        } catch (Exception e) when (e is FormatException or JsonException or ArgumentOutOfRangeException) {
+            return default;
         }
     }
 }

src/Capacitor.Cli.Core/Http/BearerRejectionReportHandler.cs

@@ -0,0 +1,252 @@
+using System.Net;
+using System.Net.Http.Headers;
+using System.Net.WebSockets;
+using System.Text;
+using System.Text.Json;
+using Capacitor.Cli.Core.Auth;
+
+namespace Capacitor.Cli.Core.Http;
+
+/// <summary>
+/// Reports each 401 with what the client can see of it: the server's <c>error</c> code and the
+/// presented bearer's subject, issue time and expiry against local time — never the bearer itself.
+/// Observes only; the response reaches the caller unchanged. Must sit inside whatever applies the
+/// bearer, so the request it sees carries the one the server refused.
+/// </summary>
+internal sealed class BearerRejectionReportHandler(TimeProvider time, Action<string> report) : DelegatingHandler {
+    const int MaxBodyBytes = 4096;
+
+    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken ct) {
+        var response = await base.SendAsync(request, ct);
+
+        if (response.StatusCode != HttpStatusCode.Unauthorized) return response;
+
+        var bearer = request.Headers.Authorization is { Scheme: var scheme, Parameter: { Length: > 0 } token }
+                  && scheme.Equals("Bearer", StringComparison.OrdinalIgnoreCase)
+            ? token
+            : null;
+
+        try {
+            var errorCode = await ReadErrorCodeAsync(response, ct)
+                         ?? ChallengeError(response.Headers.WwwAuthenticate.Select(c => c.ToString()));
+
+            report(Describe(request.Method.Method, request.RequestUri, errorCode, bearer, time.GetUtcNow()));
+        } catch (Exception ex) when (ex is not OperationCanceledException) {
+            // A diagnostic must never change what the caller gets back.
+        }
+
+        return response;
+    }
+
+    /// <summary>
+    /// A SignalR <c>WebSocketFactory</c> body. Over HTTP/1.1 SignalR opens the WebSocket itself, outside
+    /// any configured message handler, so a 401 on the upgrade would otherwise go unreported. Sets what
+    /// SignalR's own factory sets that the server acts on — the bearer, and <c>X-Requested-With</c>, which
+    /// makes cookie auth answer 401 instead of redirecting.
+    /// </summary>
+    public static async ValueTask<WebSocket> ConnectWebSocketAsync(
+            Uri uri, Func<Task<string?>>? accessTokenProvider, TimeProvider time, Action<string> report, CancellationToken ct) {
+        var webSocket = new ClientWebSocket();
+
+        webSocket.Options.CollectHttpResponseDetails = true;
+        webSocket.Options.SetRequestHeader("X-Requested-With", "XMLHttpRequest");
+
+        var bearer = accessTokenProvider is null ? null : await accessTokenProvider();
+
+        if (!string.IsNullOrWhiteSpace(bearer)) webSocket.Options.SetRequestHeader("Authorization", $"Bearer {bearer}");
+
+        try {
+            await webSocket.ConnectAsync(uri, ct);
+
+            return webSocket;
+        } catch (WebSocketException) {
+            if (webSocket.HttpStatusCode == HttpStatusCode.Unauthorized) {
+                try {
+                    var challenges = webSocket.HttpResponseHeaders?.TryGetValue("WWW-Authenticate", out var values) == true
+                        ? values
+                        : null;
+
+                    report(Describe("GET", uri, ChallengeError(challenges), string.IsNullOrWhiteSpace(bearer) ? null : bearer, time.GetUtcNow()));
+                } catch {
+                    // A diagnostic must never change the exception the caller sees.
+                }
+            }
+
+            webSocket.Dispose();
+
+            throw;
+        } catch {
+            webSocket.Dispose();
+
+            throw;
+        }
+    }
+
+    // The server names the error in an RFC 6750 challenge too: `Bearer error="invalid_token"`. It is the
+    // only place a refused WebSocket upgrade carries it, since the client never sees that response's body.
+    // Only a Bearer challenge's error describes the refused bearer; another scheme's is ignored.
+    internal static string? ChallengeError(IEnumerable<string>? challenges) {
+        foreach (var challenge in challenges ?? []) {
+            if (!AuthenticationHeaderValue.TryParse(challenge, out var parsed)
+                    || !parsed.Scheme.Equals("Bearer", StringComparison.OrdinalIgnoreCase)
+                    || parsed.Parameter is not { } parameters) {
+                continue;
+            }
+
+            foreach (var (name, value) in AuthParams(parameters)) {
+                if (name.Equals("error", StringComparison.OrdinalIgnoreCase)) return value.Length > 0 ? value : null;
+            }
+        }
+
+        return null;
+    }
+
+    // RFC 7235 auth-params: `name=token` or `name="quoted, \"escaped\" text"`, comma-separated. A comma or
+    // `error=` inside a quoted value belongs to that value and must not start a parameter of its own.
+    static IEnumerable<(string Name, string Value)> AuthParams(string parameters) {
+        var i = 0;
+
+        while (i < parameters.Length) {
+            while (i < parameters.Length && (parameters[i] == ',' || char.IsWhiteSpace(parameters[i]))) i++;
+
+            var nameStart = i;
+
+            while (i < parameters.Length && parameters[i] != '=' && parameters[i] != ',') i++;
+
+            var name = parameters[nameStart..i].Trim();
+
+            if (i >= parameters.Length || parameters[i] != '=') continue;
+
+            i++;
+
+            while (i < parameters.Length && char.IsWhiteSpace(parameters[i])) i++;
+
+            var value = new StringBuilder();
+
+            if (i < parameters.Length && parameters[i] == '"') {
+                for (i++; i < parameters.Length && parameters[i] != '"'; i++) {
+                    if (parameters[i] == '\\' && i + 1 < parameters.Length) i++;
+
+                    value.Append(parameters[i]);
+                }
+
+                i++;
+            } else {
+                while (i < parameters.Length && parameters[i] != ',') value.Append(parameters[i++]);
+            }
+
+            yield return (name, value.ToString().Trim());
+        }
+    }
+
+    internal static string Describe(string method, Uri? uri, string? errorCode, string? bearer, DateTimeOffset now) =>
+        $"401 from {method} {uri?.AbsolutePath}: server error={Printable(errorCode ?? "-")}; "
+      + $"{(bearer is null ? "no bearer sent" : DescribeBearer(bearer, now))}; local_now={now:o}";
+
+    // The error code and the bearer's subject come from outside; a control character would let either
+    // forge what reads as a further log line.
+    internal static string Printable(string value) {
+        const int max = 200;
+
+        var clipped = value.Length > max ? value[..max] + "…" : value;
+
+        return clipped.Any(char.IsControl) ? string.Concat(clipped.Select(c => char.IsControl(c) ? '?' : c)) : clipped;
+    }
+
+    static string DescribeBearer(string token, DateTimeOffset now) {
+        var exp = JwtClaims.TryGetTime(token, "exp");
+        var iat = JwtClaims.TryGetTime(token, "iat");
+        var sub = JwtClaims.TryGetString(token, "sub");
+
+        if (exp is null && iat is null && sub is null) return "bearer is not a readable JWT";
+
+        var expiresIn = exp is { } e ? $" ({(long)(e - now).TotalSeconds}s from now)" : "";
+
+        return $"bearer sub={Printable(sub ?? "-")} iat={iat?.ToString("o") ?? "-"} exp={exp?.ToString("o") ?? "-"}{expiresIn}";
+    }
+
+    // The server answers a refused bearer with {"error": "...", "message": "..."}. Reads at most one byte
+    // past the cap and puts back everything read, so the caller receives the body intact at any size.
+    static async Task<string?> ReadErrorCodeAsync(HttpResponseMessage response, CancellationToken ct) {
+        var original = response.Content;
+        var body     = await original.ReadAsStreamAsync(ct);
+        var head     = new byte[MaxBodyBytes + 1];
+        var read     = 0;
+
+        while (read < head.Length) {
+            var n = await body.ReadAsync(head.AsMemory(read), ct);
+
+            if (n == 0) break;
+
+            read += n;
+        }
+
+        var complete = read <= MaxBodyBytes;
+
+        HttpContent replacement = complete
+            ? new ByteArrayContent(head, 0, read)
+            : new StreamContent(new PrefixedStream(head.AsMemory(0, read), body));
+
+        foreach (var header in original.Headers) replacement.Headers.TryAddWithoutValidation(header.Key, header.Value);
+
+        response.Content = replacement;
+
+        // An oversized body's stream now belongs to the replacement; the original must not close it.
+        if (!complete) return null;
+
+        original.Dispose();
+
+        try {
+            using var doc = JsonDocument.Parse(Encoding.UTF8.GetString(head, 0, read));
+
+            return doc.RootElement.Str("error");
+        } catch (JsonException) {
+            return null;
+        }
+    }
+
+    // The bytes already read, then the rest of the original stream.
+    sealed class PrefixedStream(ReadOnlyMemory<byte> prefix, Stream rest) : Stream {
+        int _offset;
+
+        public override bool CanRead  => true;
+        public override bool CanSeek  => false;
+        public override bool CanWrite => false;
+        public override long Length   => throw new NotSupportedException();
+        public override long Position { get => throw new NotSupportedException(); set => throw new NotSupportedException(); }
+
+        public override int Read(byte[] buffer, int offset, int count) => Read(buffer.AsSpan(offset, count));
+
+        public override int Read(Span<byte> buffer) {
+            if (_offset < prefix.Length) return CopyPrefix(buffer);
+
+            return rest.Read(buffer);
+        }
+
+        public override Task<int> ReadAsync(byte[] buffer, int offset, int count, CancellationToken ct) =>
+            ReadAsync(buffer.AsMemory(offset, count), ct).AsTask();
+
+        public override ValueTask<int> ReadAsync(Memory<byte> buffer, CancellationToken ct = default) =>
+            _offset < prefix.Length ? ValueTask.FromResult(CopyPrefix(buffer.Span)) : rest.ReadAsync(buffer, ct);
+
+        int CopyPrefix(Span<byte> buffer) {
+            var n = Math.Min(buffer.Length, prefix.Length - _offset);
+
+            prefix.Span.Slice(_offset, n).CopyTo(buffer);
+            _offset += n;
+
+            return n;
+        }
+
+        protected override void Dispose(bool disposing) {
+            if (disposing) rest.Dispose();
+
+            base.Dispose(disposing);
+        }
+
+        public override void Flush() { }
+        public override long Seek(long offset, SeekOrigin origin) => throw new NotSupportedException();
+        public override void SetLength(long value) => throw new NotSupportedException();
+        public override void Write(byte[] buffer, int offset, int count) => throw new NotSupportedException();
+    }
+}

src/Capacitor.Cli.Daemon/Services/ServerConnection.cs

@@ -5,6 +5,7 @@
 using Capacitor.Cli.Core.Auth;
 using Capacitor.Cli.Core.Config;
 using Capacitor.Cli.Core.Eval.Contracts;
+using Capacitor.Cli.Core.Http;
 using Microsoft.AspNetCore.SignalR.Client;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Logging;
@@ -209,7 +210,14 @@ public ServerConnection(
         _tokens          = tokens;
         _logger          = logger;
         _statusNotifier  = statusNotifier ?? new();
-        _eventQueue      = new(config, tokens, time, loggerFactory.CreateLogger<AgentRunEventQueue>(), new HttpClient());
+
+        // A refused bearer is logged with its expiry and the server's error code on both lanes that
+        // carry it, so a 401 can be told apart from a lapsed token without the server's log.
+        void ReportRejection(string report) => logger.LogWarning("Server refused the daemon's bearer — {Report}", report);
+
+        _eventQueue = new(
+            config, tokens, time, loggerFactory.CreateLogger<AgentRunEventQueue>(),
+            new HttpClient(new BearerRejectionReportHandler(time, ReportRejection) { InnerHandler = new HttpClientHandler() }));
 
         _hub = new HubConnectionBuilder()
             .WithUrl(
@@ -220,6 +228,10 @@ public ServerConnection(
 
                         return resolution.Tokens?.AccessToken;
                     };
+                    options.HttpMessageHandlerFactory = inner =>
+                        new BearerRejectionReportHandler(time, ReportRejection) { InnerHandler = inner };
+                    options.WebSocketFactory = (context, ct) => BearerRejectionReportHandler.ConnectWebSocketAsync(
+                        context.Uri, context.Options.AccessTokenProvider, time, ReportRejection, ct);
                 }
             )
             .WithAutomaticReconnect(new RetryPolicy())

src/Capacitor.Cli/Commands/WatchCommand.cs

@@ -52,6 +52,10 @@ internal HubConnection BuildHubConnection(string hubUrl) {
                     // outage must send whatever the credential is by then, not the one this watcher
                     // started with.
                     options.AccessTokenProvider = async () => (await credentials.ResolveAsync(default)).Bearer;
+                    options.HttpMessageHandlerFactory = inner =>
+                        new BearerRejectionReportHandler(time, report => Log(time, report)) { InnerHandler = inner };
+                    options.WebSocketFactory = (context, ct) => BearerRejectionReportHandler.ConnectWebSocketAsync(
+                        context.Uri, context.Options.AccessTokenProvider, time, report => Log(time, report), ct);
                 }
             )
             .WithAutomaticReconnect(new InfiniteRetryPolicy())

test/Capacitor.Cli.Core.Tests.Unit/Auth/JwtClaimsTests.cs

@@ -44,4 +44,19 @@ public async Task PayloadNeedingBase64PaddingParses() {
     [Arguments("null")]
     public async Task NonObjectPayloadIsNullNeverThrows(string payload) =>
         await Assert.That(JwtClaims.TryGetString(Token(payload), "sub")).IsNull();
+
+    [Test]
+    public async Task ReadsANumericDateClaim() =>
+        await Assert.That(JwtClaims.TryGetTime(Token("""{"exp":1790000000}"""), "exp"))
+            .IsEqualTo(DateTimeOffset.FromUnixTimeSeconds(1790000000));
+
+    [Test]
+    [Arguments("""{"exp":"soon"}""")]
+    [Arguments("""{"sub":"u"}""")]
+    [Arguments("""{"exp":1e300}""")]
+    [Arguments("null")]
+    [Arguments("[1]")]
+    [Arguments("\"text\"")]
+    public async Task ANonNumericOrMissingTimeIsNullNeverThrows(string payload) =>
+        await Assert.That(JwtClaims.TryGetTime(Token(payload), "exp")).IsNull();
 }