diff --git a/README.md b/README.md index 2eeb158..3742022 100644 --- a/README.md +++ b/README.md @@ -80,6 +80,52 @@ The SDK development workflow: The SDK follows .NET best practices and conventions while providing a clean, maintainable codebase for GetStream's Feeds API integration. +## Structured Logging + +Pass `Logger` on `StreamOptions` (or `ClientBuilder.Logger(...)`) to receive structured events via `Microsoft.Extensions.Logging.ILogger`. No logger set means no output; the SDK never changes the logger's configured level. Four canonical events, matching the cross-SDK logging spec: + +| Event (dotted name, message prefix) | Level | Emitted | +|---|---|---| +| `client.initialized` | INFO | Once, at `BaseClient` construction | +| `http.request.sent` | DEBUG | Before every request is sent | +| `http.response.received` | DEBUG | After any HTTP response, including 4xx/5xx | +| `http.request.failed` | ERROR | Only on a transport failure (no HTTP response received) | + +.NET's `ILogger` uses PascalCase message-template placeholders (`{Method}`, `{StatusCode}`, ...). Each maps to a canonical snake_case field name used identically across all GetStream SDKs: + +| Event | Placeholder | Canonical field | +|---|---|---| +| `client.initialized` | `{SdkName}` | `stream.sdk.name` | +| | `{SdkVersion}` | `stream.sdk.version` | +| | `{MaxConnsPerHost}` | `stream.client.max_conns_per_host` | +| | `{IdleTimeoutSeconds}` | `stream.client.idle_timeout_seconds` | +| | `{ConnectTimeoutSeconds}` | `stream.client.connect_timeout_seconds` | +| | `{RequestTimeoutSeconds}` | `stream.client.request_timeout_seconds` | +| | `{GzipEnabled}` | `stream.client.gzip_enabled` | +| | `{UserHttpClient}` | `stream.client.user_http_client` | +| | `{LogBodies}` | `stream.client.log_bodies` | +| `http.request.sent` | `{Method}` | `method` | +| | `{Path}` | `path` | +| | `{Query}` | `query` (redacted) | +| | `{Body}` | `body` (redacted; only present when `LogBodies=true`) | +| `http.response.received` | `{Method}` | `method` | +| | `{Path}` | `path` | +| | `{StatusCode}` | `status_code` | +| | `{BodySize}` | `body_size` (bytes) | +| | `{DurationMs}` | `duration_ms` | +| | `{Body}` | `body` (redacted; only present when `LogBodies=true`) | +| `http.request.failed` | `{Method}` | `method` | +| | `{Path}` | `path` | +| | `{ErrorType}` | `error.type` | +| | `{DurationMs}` | `duration_ms` | +| | `{Message}` | `error.message` (redacted) | + +`error.type` is one of `connection_reset`, `timeout`, `dns_failure`, `tls_handshake_failed`, `unknown` (see `GetStreamTransportException.ErrorType`). + +**Redaction (always on, no opt-out):** query values for `api_key`/`api_secret`/`token` (case-insensitive) become ``; top-level JSON body keys `api_secret`/`token`/`password` become `` (shallow, key names are preserved). No header values are ever logged. `error.message` is additionally scrubbed for any `api_key=`/`api_secret=`/`token=` value appearing anywhere in the free-form transport-exception text. + +**Bodies are not logged by default.** Set `StreamOptions.LogBodies = true` (or `ClientBuilder.LogBodies(true)`) to opt in; body content is still key-redacted as above. Enabling it emits exactly one WARN line at construction. + ## Release Process Releases use two paths, both handled by `.github/workflows/release.yml`: diff --git a/src/AssemblyInfo.cs b/src/AssemblyInfo.cs new file mode 100644 index 0000000..d6d1022 --- /dev/null +++ b/src/AssemblyInfo.cs @@ -0,0 +1,3 @@ +// Grants the test assembly access to internal members (e.g. LogRedaction) without +// widening any public API surface. Test assembly name matches tests/stream-feed-net-test.csproj. +[assembly: System.Runtime.CompilerServices.InternalsVisibleTo("stream-feed-net-test")] diff --git a/src/Client.cs b/src/Client.cs index 724d87b..21dff9d 100644 --- a/src/Client.cs +++ b/src/Client.cs @@ -21,6 +21,7 @@ public class BaseClient : IClient private readonly HttpClient _httpClient; private readonly Microsoft.Extensions.Logging.ILogger? _logger; private readonly bool _userHttpClient; + private readonly bool _logBodies; protected string ApiKey; protected string ApiSecret; protected string BaseUrl; @@ -58,6 +59,7 @@ public BaseClient(StreamOptions opts) ApiSecret = opts.ApiSecret; BaseUrl = opts.BaseUrl; _logger = opts.Logger; + _logBodies = opts.LogBodies; if (opts.HttpClient != null) { @@ -78,7 +80,7 @@ public BaseClient(StreamOptions opts) Converters = { new NanosecondTimestampConverter(), new FeedOwnCapabilityConverter(), new ChannelOwnCapabilityConverter(), new OwnCapabilityConverter() } }; - LogConstruction(opts); + LogInitialized(opts); } private static HttpClient BuildDefaultHttpClient(StreamOptions opts) @@ -96,19 +98,34 @@ private static HttpClient BuildDefaultHttpClient(StreamOptions opts) return new HttpClient(handler) { Timeout = opts.RequestTimeout }; } - private void LogConstruction(StreamOptions opts) + /// + /// Emits the client.initialized INFO event exactly once (logging spec ยง6.1), then a one-shot + /// WARN when is enabled. See README "Structured Logging" for + /// the PascalCase-placeholder-to-canonical-field mapping. + /// + private void LogInitialized(StreamOptions opts) { if (_logger == null) return; - if (_userHttpClient) - { - _logger.LogInformation( - "connection pool: user_http_client=true (5 knobs not applied)"); - } - else + + // The SDK only wires gzip itself on the default-built handler (CHA-2961); when the caller + // supplies their own HttpClient (escape hatch), gzip is entirely the caller's concern. + // Bools are rendered lowercase explicitly: bool.ToString() defaults to "True"/"False", + // which would be the only capitalized values among an otherwise all-lowercase field set + // shared verbatim across the 6-SDK logging spec. + var gzipEnabled = (!_userHttpClient).ToString().ToLowerInvariant(); + var userHttpClient = _userHttpClient.ToString().ToLowerInvariant(); + var logBodies = opts.LogBodies.ToString().ToLowerInvariant(); + + _logger.LogInformation( + "client.initialized stream.sdk.name={SdkName} stream.sdk.version={SdkVersion} stream.client.max_conns_per_host={MaxConnsPerHost} stream.client.idle_timeout_seconds={IdleTimeoutSeconds} stream.client.connect_timeout_seconds={ConnectTimeoutSeconds} stream.client.request_timeout_seconds={RequestTimeoutSeconds} stream.client.gzip_enabled={GzipEnabled} stream.client.user_http_client={UserHttpClient} stream.client.log_bodies={LogBodies}", + "getstream-net", VersionName, + opts.MaxConnsPerHost, opts.IdleTimeout.TotalSeconds, opts.ConnectTimeout.TotalSeconds, opts.RequestTimeout.TotalSeconds, + gzipEnabled, userHttpClient, logBodies); + + if (opts.LogBodies) { - _logger.LogInformation( - "connection pool: max_conns_per_host={MaxConnsPerHost} idle_timeout={IdleTimeout} connect_timeout={ConnectTimeout} request_timeout={RequestTimeout} user_http_client=false", - opts.MaxConnsPerHost, opts.IdleTimeout, opts.ConnectTimeout, opts.RequestTimeout); + _logger.LogWarning( + "HTTP request/response bodies will be logged. Auth headers and known-secret fields are still redacted, but other sensitive data (messages, PII) may appear in logs. Disable for production."); } } @@ -130,6 +147,7 @@ public async Task> MakeRequestAsync> MakeRequestAsync> MakeRequestAsync> MakeRequestAsync(); } + // CHA-2957: near-duplicate send path, not exposed on IClient; intentionally not instrumented with structured logging. public async Task> MakeRequestAsyncDebug( string method, string path, diff --git a/src/ClientBuilder.cs b/src/ClientBuilder.cs index bb662c3..28afae4 100644 --- a/src/ClientBuilder.cs +++ b/src/ClientBuilder.cs @@ -37,6 +37,7 @@ public class ClientBuilder private TimeSpan _requestTimeout = TimeSpan.FromSeconds(30); private System.Net.Http.HttpClient? _httpClient; private ILogger? _logger; + private bool _logBodies; /// /// Set the API key @@ -101,6 +102,9 @@ public ClientBuilder EnvPath(string path) /// Opt-in INFO log on construction. public ClientBuilder Logger(ILogger logger) { _logger = logger; return this; } + /// Opt-in body logging (DEBUG events); shallow secret-key redaction still applies. Default false. + public ClientBuilder LogBodies(bool enabled) { _logBodies = enabled; return this; } + /// /// Create a client builder that loads configuration from environment variables /// @@ -211,6 +215,7 @@ private StreamOptions BuildStreamOptions() RequestTimeout = _requestTimeout, HttpClient = _httpClient, Logger = _logger, + LogBodies = _logBodies, }; } diff --git a/src/LogRedaction.cs b/src/LogRedaction.cs new file mode 100644 index 0000000..653b4f6 --- /dev/null +++ b/src/LogRedaction.cs @@ -0,0 +1,60 @@ +using System; +using System.Linq; +using System.Text.Json; +using System.Text.Json.Nodes; +using System.Text.RegularExpressions; + +namespace GetStream +{ + /// Redaction helpers for the SDK's structured log events. Shallow by design. + internal static class LogRedaction + { + internal const string Redacted = ""; + private static readonly string[] QueryParams = { "api_key", "api_secret", "token" }; + private static readonly string[] BodyKeys = { "api_secret", "token", "password" }; + + // CHA-2957 secret-leak guard: scrubs the same three secret query params wherever + // they appear in a free-form string (e.g. a transport exception's Message), not + // just in a well-formed query string. + private static readonly Regex MessageSecretPattern = new( + @"(api_key|api_secret|token)=[^&\s]*", + RegexOptions.IgnoreCase | RegexOptions.Compiled); + + internal static string RedactQuery(string query) + { + if (string.IsNullOrEmpty(query)) return query; + return string.Join("&", query.Split('&').Select(pair => + { + var idx = pair.IndexOf('='); + if (idx < 0) return pair; + var name = pair[..idx]; + return QueryParams.Contains(name.ToLowerInvariant()) ? $"{name}={Redacted}" : pair; + })); + } + + internal static string RedactJsonBody(string body) + { + if (string.IsNullOrEmpty(body)) return body; + try + { + if (JsonNode.Parse(body) is not JsonObject obj) return body; + var changed = false; + foreach (var key in BodyKeys) + { + if (obj.ContainsKey(key)) { obj[key] = Redacted; changed = true; } + } + return changed ? obj.ToJsonString() : body; + } + catch (JsonException) + { + return body; + } + } + + internal static string RedactMessage(string message) + { + if (string.IsNullOrEmpty(message)) return message; + return MessageSecretPattern.Replace(message, m => $"{m.Groups[1].Value}={Redacted}"); + } + } +} diff --git a/src/StreamOptions.cs b/src/StreamOptions.cs index 3f70577..4708b17 100644 --- a/src/StreamOptions.cs +++ b/src/StreamOptions.cs @@ -38,5 +38,8 @@ public class StreamOptions /// When set, the SDK emits one INFO line on construction. public ILogger? Logger { get; set; } + + /// Opt-in body logging on the DEBUG events; known-secret keys stay redacted. Default false. + public bool LogBodies { get; set; } } } diff --git a/tests/ConnectionPoolTests.cs b/tests/ConnectionPoolTests.cs index 0de35a7..9c084ff 100644 --- a/tests/ConnectionPoolTests.cs +++ b/tests/ConnectionPoolTests.cs @@ -196,11 +196,14 @@ public void BaseClient_InfoLog_OnConstruction_WithDefaults() }); Assert.That(capture.Infos.Count, Is.EqualTo(1), "exactly one INFO line on construction"); var msg = capture.Infos[0]; - Assert.That(msg, Does.Contain("max_conns_per_host=5")); - Assert.That(msg, Does.Contain("idle_timeout=00:00:55")); - Assert.That(msg, Does.Contain("connect_timeout=00:00:10")); - Assert.That(msg, Does.Contain("request_timeout=00:00:30")); - Assert.That(msg, Does.Contain("user_http_client=false")); + Assert.That(msg, Does.StartWith("client.initialized")); + Assert.That(msg, Does.Contain("stream.client.max_conns_per_host=5")); + Assert.That(msg, Does.Contain("stream.client.idle_timeout_seconds=55")); + Assert.That(msg, Does.Contain("stream.client.connect_timeout_seconds=10")); + Assert.That(msg, Does.Contain("stream.client.request_timeout_seconds=30")); + Assert.That(msg, Does.Contain("stream.client.user_http_client=false")); + Assert.That(msg, Does.Contain("stream.client.gzip_enabled=true")); + Assert.That(msg, Does.Contain("stream.client.log_bodies=false")); } [Test] @@ -215,8 +218,9 @@ public void BaseClient_InfoLog_OnConstruction_WithUserHttpClient() Logger = capture, }); Assert.That(capture.Infos.Count, Is.EqualTo(1)); - Assert.That(capture.Infos[0], Does.Contain("user_http_client=true")); - Assert.That(capture.Infos[0], Does.Contain("5 knobs not applied")); + Assert.That(capture.Infos[0], Does.Contain("stream.client.user_http_client=true")); + Assert.That(capture.Infos[0], Does.Contain("stream.client.gzip_enabled=false"), + "escape hatch: SDK doesn't wire gzip itself, so it can't claim gzip_enabled=true"); } [Test] diff --git a/tests/LoggingTests.cs b/tests/LoggingTests.cs new file mode 100644 index 0000000..6fbda29 --- /dev/null +++ b/tests/LoggingTests.cs @@ -0,0 +1,157 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Net; +using System.Net.Http; +using System.Text; +using System.Threading; +using System.Threading.Tasks; +using GetStream; +using Microsoft.Extensions.Logging; +using NUnit.Framework; + +namespace GetStream.Tests +{ + [TestFixture] + public class LoggingTests + { + private sealed class RecordingLogger : ILogger + { + public readonly List<(LogLevel Level, string Message)> Entries = new(); + + public IDisposable? BeginScope(TState state) where TState : notnull => null; + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) + => Entries.Add((logLevel, formatter(state, exception))); + + public List<(LogLevel Level, string Message)> Named(string ev) => Entries.Where(e => e.Message.StartsWith(ev)).ToList(); + } + + private sealed class CannedHandler : HttpMessageHandler + { + private readonly HttpStatusCode _status; + private readonly string _body; + private readonly bool _throw; + + public CannedHandler(HttpStatusCode status, string body, bool throwTransport = false) + { + _status = status; _body = body; _throw = throwTransport; + } + + protected override Task SendAsync(HttpRequestMessage request, CancellationToken ct) + { + if (_throw) throw new HttpRequestException("reset"); + return Task.FromResult(new HttpResponseMessage(_status) { Content = new StringContent(_body, Encoding.UTF8, "application/json") }); + } + } + + private static (BaseClient, RecordingLogger) Build(HttpMessageHandler handler, bool logBodies = false) + { + var logger = new RecordingLogger(); + var client = new BaseClient(new StreamOptions + { + ApiKey = "key", + // HMAC-SHA256 requires a >= 128-bit (16-byte) key; a bare "secret" throws + // ArgumentOutOfRangeException at JWT-signing time (see GzipTests.cs for the + // same constraint documented on the existing dummy secrets in this repo). + ApiSecret = "secret-that-is-long-enough-for-hmac-sha256", + HttpClient = new HttpClient(handler) { BaseAddress = new Uri("http://localhost") }, + Logger = logger, + LogBodies = logBodies, + }); + return (client, logger); + } + + private static Task Get(BaseClient c) => c.MakeRequestAsync>("GET", "/api/v2/app", null, null, null); + + [Test] + public void ClientInitializedOnceWithSchema() + { + var (_, logger) = Build(new CannedHandler(HttpStatusCode.OK, "{}")); + var inits = logger.Named("client.initialized"); + Assert.That(inits, Has.Count.EqualTo(1)); + Assert.That(inits[0].Message, Does.Contain("getstream-net")); + } + + [Test] + public async Task SentAndReceivedOnSuccess() + { + var (client, logger) = Build(new CannedHandler(HttpStatusCode.OK, "{}")); + await Get(client); + Assert.That(logger.Named("http.request.sent"), Has.Count.EqualTo(1)); + var received = logger.Named("http.response.received"); + Assert.That(received, Has.Count.EqualTo(1)); + Assert.That(received[0].Message, Does.Contain("200")); + } + + [Test] + public void ErrorStatusIsReceivedNotFailed() + { + var (client, logger) = Build(new CannedHandler(HttpStatusCode.InternalServerError, "{\"code\":1,\"message\":\"boom\"}")); + Assert.ThrowsAsync(() => Get(client)); + Assert.That(logger.Named("http.response.received"), Has.Count.EqualTo(1)); + Assert.That(logger.Named("http.request.failed"), Is.Empty); + } + + [Test] + public void TransportFailureEmitsFailed() + { + var (client, logger) = Build(new CannedHandler(HttpStatusCode.OK, "{}", throwTransport: true)); + Assert.ThrowsAsync(() => Get(client)); + var failed = logger.Named("http.request.failed"); + Assert.That(failed, Has.Count.EqualTo(1)); + Assert.That(failed[0].Level, Is.EqualTo(LogLevel.Error)); + } + + [Test] + public async Task QueryRedaction() + { + var (client, logger) = Build(new CannedHandler(HttpStatusCode.OK, "{}")); + await client.MakeRequestAsync>("GET", "/api/v2/app", new Dictionary { ["api_key"] = "sekret" }, null, null); + foreach (var e in logger.Entries) + Assert.That(e.Message, Does.Not.Contain("sekret")); + } + + [Test] + public async Task LogBodiesOptInWithRedactionAndWarn() + { + // The secret value must not be a substring of its own key name ("token" would make + // "tok" unavoidably present in output even after the value is redacted). + var (client, logger) = Build(new CannedHandler(HttpStatusCode.OK, "{\"token\":\"sekrit-val\",\"keep\":\"v\"}"), logBodies: true); + Assert.That(logger.Entries.Count(e => e.Level == LogLevel.Warning && e.Message.Contains("bodies will be logged")), Is.EqualTo(1)); + await Get(client); + var received = logger.Named("http.response.received")[0]; + Assert.That(received.Message, Does.Contain("keep")); + Assert.That(received.Message, Does.Not.Contain("sekrit-val")); + } + + [Test] + public void RedactionHelpers() + { + Assert.That(LogRedaction.RedactQuery("api_key=sekret&x=1"), Is.EqualTo("api_key=&x=1")); + var body = LogRedaction.RedactJsonBody("{\"api_secret\":\"s\",\"password\":\"p\",\"keep\":\"v\"}"); + Assert.That(body, Does.Not.Contain("\"s\"").And.Contain("\"keep\":\"v\"")); + Assert.That(LogRedaction.RedactJsonBody("not json"), Is.EqualTo("not json")); + } + + // -- CHA-2957 proactive secret-leak guard: error.message must never carry a raw secret -- + + [Test] + public void RedactMessage_RedactsSecretQueryValuesInFreeText() + { + var msg = "transport error (unknown): call to https://chat.stream-io-api.com/api/v2/app?api_key=SUPERSECRETKEY&foo=bar failed"; + var redacted = LogRedaction.RedactMessage(msg); + Assert.That(redacted, Does.Contain("api_key=")); + Assert.That(redacted, Does.Not.Contain("SUPERSECRETKEY")); + } + + [Test] + public void RedactMessage_RedactsAllThreeKeys_PreservesNonSecretParam() + { + var msg = "api_key=a&api_secret=b&token=c&foo=bar"; + var redacted = LogRedaction.RedactMessage(msg); + Assert.That(redacted, Is.EqualTo("api_key=&api_secret=&token=&foo=bar")); + } + } +}