diff --git a/docs/logging.md b/docs/logging.md new file mode 100644 index 000000000..474be675d --- /dev/null +++ b/docs/logging.md @@ -0,0 +1,296 @@ +# Logging + +Fluxzy.Core emits structured logs through `Microsoft.Extensions.Logging.Abstractions` +and per-exchange traces through `System.Diagnostics.ActivitySource`. Both are wired +through one optional parameter on the `Proxy` constructor. + +## Quickstart + +```csharp +using Microsoft.Extensions.Logging; + +using var loggerFactory = LoggerFactory.Create(builder => builder + .SetMinimumLevel(LogLevel.Debug) + .AddSimpleConsole(o => o.IncludeScopes = true)); + +var setting = FluxzySetting.CreateLocalRandomPort(); + +await using var proxy = new Proxy(setting, loggerFactory: loggerFactory); +proxy.Run(); +``` + +When `loggerFactory` is null (the default), `NullLoggerFactory.Instance` is used and +no logs are emitted — zero overhead, no behaviour change for existing callers. + +For OpenTelemetry traces, register the `Fluxzy.Core` `ActivitySource`: + +```csharp +using OpenTelemetry.Trace; + +Sdk.CreateTracerProviderBuilder() + .AddSource("Fluxzy.Core") + .AddOtlpExporter() + .Build(); +``` + +If the inbound HTTP request carries a `traceparent` header (W3C Trace Context), +Fluxzy reads it and starts the per-exchange Activity as a child — so traces stitch +end-to-end across upstream callers and downstream origins. + +## Logging scopes + +Every event is fired inside two nested scopes, so structured-logging backends +(Serilog, Seq, Datadog, etc.) automatically attach the scope properties to each +line — there's no need to repeat them in message templates. + +**Connection scope** (one per inbound TCP connection): + +| Property | Meaning | +|---------------------|-----------------------------------------------| +| `ProxyConnectionId` | Per-`Proxy`-instance monotonic counter | +| `DownstreamRemote` | Inbound `IPEndPoint` from the client | +| `DownstreamLocal` | Inbound `IPEndPoint` Fluxzy is bound to | + +**Exchange scope** (one per HTTP exchange — request/response pair): + +| Property | Meaning | +|---------------|------------------------------------------| +| `ExchangeId` | `Exchange.Id` (monotonic) | +| `Authority` | Target `host:port` | +| `Method` | HTTP method (`GET`, `POST`, …) | +| `Path` | Request path | +| `HttpVersion` | `HTTP/1.1`, `HTTP/2`, … | + +## EventId schema + +| Range | Tier | +|------------|----------------------------------------------| +| 1000-1099 | Lifecycle (connection / exchange) — Debug | +| 1100-1199 | Pool / transport — Debug | +| 1200-1299 | TLS — reserved for future | +| 1099 | Exchange envelope (full headers) — Trace | +| 2000-2999 | Warnings | +| 3000-3999 | Errors | + +EventIds are stable contract — changes are breaking. + +## Event catalogue + +All properties listed below are **in addition to** the scope properties above. + +### 1001 `ClientConnectionAccepted` — Debug + +Fired once per inbound TCP connection, immediately after the connection scope opens. + +| Property | Type | Meaning | +|---------------------|--------|------------------------------------------| +| `ConcurrentCount` | `int` | Concurrent connections being processed | +| `CloseImmediately` | `bool` | True when overall-concurrency cap is hit | + +### 1002 `RequestResolutionStarted` — Debug + +Fired once per processed exchange (skipped for raw CONNECT) right after the +exchange scope opens, before pool resolution. + +| Property | Type | Meaning | +|------------------------|-----------|------------------------------------------| +| `Method` | `string` | HTTP method | +| `FullUrl` | `string` | Full reconstructed URL | +| `IsSecure` | `bool` | HTTPS | +| `IsWebSocket` | `bool` | WebSocket upgrade request | +| `HasRequestBody` | `bool` | Body present | +| `RequestContentLength` | `long` | -1 when chunked / unknown | +| `UserAgent` | `string?` | `User-Agent` header value | +| `ProcessId` | `int?` | Local process id (only when tracking on) | +| `ProcessPath` | `string?` | Local process path | + +### 1003 `DnsResolved` — Debug + +Fired in `DnsUtility.ComputeDnsUpdateExchange` after DNS resolution. + +| Property | Type | Meaning | +|----------------------|-----------|------------------------------------------| +| `HostName` | `string` | Hostname queried | +| `RemoteIp` | `string` | Resolved IP | +| `RemotePort` | `int` | Effective remote port | +| `DnsMs` | `double` | Resolution latency (0 when forced) | +| `DnsResolver` | `string` | `DefaultDnsResolver`, `DnsOverHttpsResolver`, … | +| `WasForced` | `bool` | True when a rule pre-set the IP | +| `UpstreamProxyHost` | `string?` | Upstream proxy host (when configured) | +| `UpstreamProxyPort` | `int?` | Upstream proxy port (when configured) | + +### 1004 `ConnectionPoolResolved` — Debug + +Fired once per `PoolBuilder.GetPool` success. + +| Property | Type | Meaning | +|------------------------|------------|------------------------------------------| +| `PoolType` | `string` | `Http11` / `H2` / `Mocked` / `Tunnel` / `Websocket` | +| `ReusingConnection` | `bool` | Warm reuse vs. fresh handshake | +| `GetPoolMs` | `double` | Time from receive to pool resolution | +| `ConnectionId` | `int?` | Bound `Connection.Id` (null when reused without binding) | +| `RemoteIp` / `RemotePort` | `string?` / `int?` | Resolved upstream endpoint | +| `LocalIp` / `LocalPort` | `string?` / `int?` | Bound local endpoint | +| `Alpn` | `string?` | ALPN negotiated protocol | +| `TlsProtocol` | `string?` | `Tls12` / `Tls13` / … | +| `CipherSuite` | `string?` | Negotiated cipher suite | +| `SniSent` | `string?` | SNI value (Authority hostname for HTTPS) | +| `TlsHandshakeMs` | `double?` | TLS handshake duration | +| `TcpConnectMs` | `double?` | TCP connect duration | +| `IsBlindTunnel` | `bool` | Tunnel-only (no decryption) | +| `IsMocked` | `bool` | Mocked response | + +### 1005 `RequestSending` — Debug + +Fired in H1 and H2 send paths immediately before the request header bytes go on the wire. + +| Property | Type | Meaning | +|--------------------------------|---------|--------------------------------------| +| `ConnectionId` | `int` | Bound upstream `Connection.Id` | +| `RequestHeaderLength` | `int` | Encoded header length (bytes) | +| `HasExpectContinue` | `bool` | Request carries `Expect: 100-continue` | +| `HasRequestBody` | `bool` | | +| `RequestContentLength` | `long` | -1 when chunked | +| `Chunked` | `bool` | Chunked transfer encoding | +| `RequestProcessedOnConnection` | `int` | Counter of requests on this connection | + +### 1006 `RequestSent` — Debug + +Fired after the request body finishes sending (or skipped via early Expect-100 rejection). + +| Property | Type | Meaning | +|---------------------|----------|------------------------------------------| +| `ConnectionId` | `int` | | +| `BytesSent` | `long` | Total upstream bytes sent so far | +| `RequestBodyBytes` | `long` | Body bytes (clamped to ≥0) | +| `SendMs` | `double` | Header-sending → body-sent total | +| `HeaderSendMs` | `double` | Header-sending → header-sent | +| `BodySendMs` | `double` | Header-sent → body-sent | +| `EarlyResponse` | `bool` | True when origin answered before body | + +### 1007 `ResponseHeaderReceived` — Debug + +Fired once the final (non-1xx) response header is parsed. + +| Property | Type | Meaning | +|--------------------------|-----------|------------------------------------------| +| `ConnectionId` | `int` | | +| `StatusCode` | `int` | | +| `ReasonPhrase` | `string?` | Currently null (not stored) | +| `ResponseHeaderLength` | `int` | Bytes of response header | +| `ResponseContentLength` | `long` | -1 when chunked | +| `ResponseChunked` | `bool` | | +| `ConnectionCloseRequest` | `bool` | Origin requested `Connection: close` | +| `TtfbMs` | `double` | Header-sending → response-header-end | +| `ResponseHeaderReadMs` | `double` | Header-start → header-end | +| `HasResponseBody` | `bool` | | +| `ContentEncoding` | `string?` | `Content-Encoding` header | +| `ContentType` | `string?` | `Content-Type` header | +| `Server` | `string?` | `Server` header | + +### 1008 `ExchangeCompleted` — Debug + +Fired exactly once per processed exchange, right after `await exchange.Complete`. +This is the single most useful line for postmortem analysis. + +| Property | Type | Meaning | +|--------------------------------|----------|--------------------------------------| +| `ConnectionId` | `int` | | +| `StatusCode` | `int` | | +| `FullUrl` | `string` | | +| `TotalMs` | `double` | End-to-end exchange latency | +| `DnsMs` / `GetPoolMs` / `TcpConnectMs` / `TlsHandshakeMs` | `double` | Phase latencies | +| `SendMs` / `TtfbMs` / `ResponseBodyMs` | `double` | Phase latencies | +| `TotalSent` / `TotalReceived` | `long` | | +| `RequestHeaderLength` / `ResponseHeaderLength` | `int` | | +| `ReusingConnection` | `bool` | | +| `RequestProcessedOnConnection` | `int` | | +| `ErrorCount` | `int` | `Exchange.Errors.Count` | +| `Aborted` | `bool` | Exchange aborted via rule | +| `ClosedRemote` | `bool` | Remote closed the connection | + +### 1009 `ConnectionEvicted` — Debug + +Fired in `PoolBuilder.OnConnectionFaulted` when an upstream pool is removed +(today: H2 GoAway / fault). + +| Property | Type | Meaning | +|-----------------|----------|----------------------------------------| +| `Authority` | `string` | | +| `Reason` | `string` | Free-form (`PoolFaulted` today) | +| `ConnectionId` | `int?` | H2 only (other pools null) | + +### 1010 `ConnectionOpened` — Debug + +Fired in `RemoteConnectionBuilder.OpenConnectionToRemote` once a brand-new +upstream `Connection` is fully built. + +| Property | Type | Meaning | +|----------------------|-----------|------------------------------------------| +| `ConnectionId` | `int` | | +| `Authority` | `string` | | +| `RemoteIp` / `RemotePort` | `string` / `int` | Resolved upstream | +| `LocalPort` | `int` | Bound local port | +| `HttpVersion` | `string` | `HTTP/1.1` / `HTTP/2` | +| `Alpn` | `string?` | | +| `TlsProtocol` | `string?` | | +| `CipherSuite` | `string?` | | +| `SniSent` | `string?` | | +| `TcpConnectMs` | `double` | | +| `TlsHandshakeMs` | `double` | | +| `ProxyConnectMs` | `double` | Time to negotiate upstream proxy CONNECT | +| `ViaUpstreamProxy` | `bool` | | + +### 1099 `ExchangeEnvelope` — Trace + +Fired at exchange completion when `LogLevel.Trace` is enabled. One line carrying +the full request and response headers (and trailers when present). + +| Property | Type | Meaning | +|-------------------|-----------|----------------------------------------| +| `ExchangeId` | `int` | | +| `RequestHeaders` | `string` | `Name=Value`, one per line | +| `ResponseHeaders` | `string?` | `Name=Value`, one per line | +| `Trailers` | `string?` | Response trailers when present | + +Header redaction is governed by two `FluxzySetting` properties: + +- `LogIncludeSensitiveHeaders` (default `false`): when `false`, header values + whose name appears in `LogRedactedHeaders` are replaced with + ``. +- `LogRedactedHeaders` (case-insensitive): default set is `Authorization`, + `Proxy-Authorization`, `Cookie`, `Set-Cookie`, `X-Auth-Token`. + +### 2001 `ClientConnectionInitFailed` — Warning + +Fired when the inbound client-connection initialization fails (TLS handshake +from client failed, malformed CONNECT, etc.). Carries the exception and the +client `RemoteEndPoint`. + +### 3001 `ConnectionProcessingError` — Error + +Top-level catch in `Proxy.ProcessingConnection` — fires for unexpected errors +that aren't already handled by the orchestrator's per-exchange error paths. +Carries the exception and the client `RemoteEndPoint`. + +## ActivitySource — `Fluxzy.Core` + +One `Activity` is emitted per processed exchange (`ActivityKind.Server`, +operation name `"HTTP {Method}"`). Tags follow OpenTelemetry HTTP semantic +conventions where they map cleanly: + +`http.request.method`, `url.full`, `server.address`, `server.port`, +`client.address`, `client.port`, `user_agent.original`, +`network.protocol.version`, `http.response.status_code`, +`http.request.body.size`, `http.response.body.size`. + +Fluxzy-specific tags: + +`fluxzy.exchange_id`, `fluxzy.pool.type`, `fluxzy.pool.reused`, +`fluxzy.dns.duration_ms`, `fluxzy.dns.forced`. + +`ActivityStatusCode` is set to `Error` for 5xx / aborted / errored exchanges +and `Ok` for 2xx-3xx responses. + +If the inbound request carries a W3C `traceparent` (and optional `tracestate`), +the Activity is started with that parent context so traces stitch end-to-end. diff --git a/src/Fluxzy.Core/Clients/DnsUtility.cs b/src/Fluxzy.Core/Clients/DnsUtility.cs index 4f91aad8d..fad1e2570 100644 --- a/src/Fluxzy.Core/Clients/DnsUtility.cs +++ b/src/Fluxzy.Core/Clients/DnsUtility.cs @@ -5,7 +5,10 @@ using System.Threading.Tasks; using Fluxzy.Clients.Mock; using Fluxzy.Core; +using Fluxzy.Logging; using Fluxzy.Rules; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Fluxzy.Clients { @@ -28,24 +31,32 @@ public DnsResolutionResult(IPEndPoint endPoint, DateTime dnsSolveStart, DateTime internal static class DnsUtility { public static async ValueTask - ComputeDnsUpdateExchange(Exchange exchange, - ITimingProvider timingProvider, IDnsSolver dnsSolver, - ProxyRuntimeSetting? runtimeSetting) + ComputeDnsUpdateExchange(Exchange exchange, + ITimingProvider timingProvider, IDnsSolver dnsSolver, + ProxyRuntimeSetting? runtimeSetting, + ILogger? logger = null) { var dnsSolveStart = timingProvider.Instant(); var connectHostName = exchange.Context.ProxyConfiguration?.Host ?? exchange.Authority.HostName; - + + var wasForced = exchange.Context.RemoteHostIp != null; + var ipAddress = exchange.Context.RemoteHostIp ?? await dnsSolver.SolveDns(connectHostName).ConfigureAwait(false); var dnsSolveEnd = timingProvider.Instant(); - var remotePort = exchange.Context.ProxyConfiguration?.Port ?? exchange.Context.RemoteHostPort + var remotePort = exchange.Context.ProxyConfiguration?.Port ?? exchange.Context.RemoteHostPort ?? exchange.Authority.Port; exchange.Context.RemoteHostIp = ipAddress; exchange.Context.RemoteHostPort = remotePort; + FluxzyLogEvents.LogDnsResolved( + logger ?? NullLogger.Instance, + exchange, connectHostName, ipAddress, remotePort, + dnsSolveStart, dnsSolveEnd, dnsSolver, wasForced); + var remoteEndPoint = new IPEndPoint(ipAddress, remotePort); return new(remoteEndPoint, dnsSolveStart, dnsSolveEnd); diff --git a/src/Fluxzy.Core/Clients/H11/Http11ConnectionPool.cs b/src/Fluxzy.Core/Clients/H11/Http11ConnectionPool.cs index 0b7c3e2b9..52bc61950 100644 --- a/src/Fluxzy.Core/Clients/H11/Http11ConnectionPool.cs +++ b/src/Fluxzy.Core/Clients/H11/Http11ConnectionPool.cs @@ -22,8 +22,6 @@ public class Http11ConnectionPool : IHttpConnectionPool private readonly RealtimeArchiveWriter _archiveWriter; private readonly DnsResolutionResult _resolutionResult; - private readonly H1Logger _logger; - private readonly Channel _pendingConnections; private readonly ProxyRuntimeSetting _proxyRuntimeSetting; @@ -52,8 +50,6 @@ internal Http11ConnectionPool( SingleWriter = false }); - _logger = new H1Logger(authority); - ITimingProvider.Default.Instant(); } @@ -74,9 +70,6 @@ public async ValueTask Send( exchange.HttpVersion = "HTTP/1.1"; try { - _logger.Trace(exchange, "Begin wait for authority slot"); - _logger.Trace(exchange.Id, "Acquiring slot"); - var requestDate = _timingProvider.Instant(); while (_pendingConnections.Reader.TryRead(out var state)) { @@ -90,14 +83,10 @@ public async ValueTask Send( } exchange.Connection = state.Connection; - _logger.Trace(exchange.Id, () => $"Recycling connection : {exchange.Connection.Id}"); - break; } if (exchange.Connection == null) { - _logger.Trace(exchange.Id, () => "New connection request"); - var openingResult = await _remoteConnectionBuilder.OpenConnectionToRemote( exchange, _resolutionResult , Http11Protocols, @@ -113,11 +102,11 @@ await _remoteConnectionBuilder.OpenConnectionToRemote( if (_archiveWriter != null!) _archiveWriter.Update(exchange.Connection, cancellationToken); - - _logger.Trace(exchange.Id, () => $"New connection obtained: {exchange.Connection.Id}"); } - var poolProcessing = new Http11PoolProcessing(_logger, _proxyRuntimeSetting.ExpectContinueTimeout); + var poolProcessing = new Http11PoolProcessing( + _proxyRuntimeSetting.ExpectContinueTimeout, + _proxyRuntimeSetting.GetLogger()); try { await poolProcessing.Process(exchange, buffer, exchangeScope, cancellationToken) @@ -125,9 +114,7 @@ await poolProcessing.Process(exchange, buffer, exchangeScope, cancellationToken) if (exchange.Response.Header != null) exchange.Connection.TimeoutIdleSeconds = exchange.Response.Header.TimeoutIdleSeconds; - - _logger.Trace(exchange.Id, () => "[Process] return"); - + var lastUsed = _timingProvider.Instant(); void OnExchangeCompleteFunction(Task completeTask) @@ -143,8 +130,6 @@ void OnExchangeCompleteFunction(Task completeTask) exchange.Metrics.ResponseBodyEnd = ITimingProvider.Default.Instant(); if (completeTask.Exception != null && completeTask.Exception.InnerExceptions.Any()) { - _logger.Trace(exchange.Id, () => $"Complete on error {completeTask.Exception.GetType()} : {completeTask.Exception.Message}"); - foreach (var exception in completeTask.Exception.InnerExceptions) { exchange.Errors.Add(new Error("Error while reading response", exception)); } @@ -154,13 +139,10 @@ void OnExchangeCompleteFunction(Task completeTask) if (_pendingConnections.Writer.TryWrite( new Http11ProcessingState(exchange.Connection, lastUsed))) { - _logger.Trace(exchange.Id, () => "Complete on success, recycling connection ..."); return; } } else { - _logger.Trace(exchange.Id, () => "Complete on success, closing connection ..."); - // should close connection } @@ -178,9 +160,7 @@ void OnExchangeCompleteFunction(Task completeTask) exchange.Connection = null; } - - _logger.Trace(exchange.Id, () => $"Processing error {ex}"); - + throw; } } diff --git a/src/Fluxzy.Core/Clients/H11/Http11PoolProcessing.cs b/src/Fluxzy.Core/Clients/H11/Http11PoolProcessing.cs index d9085eeff..682096887 100644 --- a/src/Fluxzy.Core/Clients/H11/Http11PoolProcessing.cs +++ b/src/Fluxzy.Core/Clients/H11/Http11PoolProcessing.cs @@ -8,21 +8,24 @@ using Fluxzy.Clients.H2.Encoder.Utils; using Fluxzy.Core; using Fluxzy.Formatters.Producers.Requests; +using Fluxzy.Logging; using Fluxzy.Misc.ResizableBuffers; using Fluxzy.Misc.Streams; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; using Org.BouncyCastle.Tls; namespace Fluxzy.Clients.H11 { internal class Http11PoolProcessing { - private readonly H1Logger _logger; private readonly TimeSpan _expectContinueTimeout; + private readonly ILogger _logger; - public Http11PoolProcessing(H1Logger logger, TimeSpan expectContinueTimeout) + public Http11PoolProcessing(TimeSpan expectContinueTimeout, ILogger? logger = null) { - _logger = logger; _expectContinueTimeout = expectContinueTimeout; + _logger = logger ?? NullLogger.Instance; } /// @@ -43,23 +46,22 @@ public async ValueTask Process(Exchange exchange, RsBuffer buffer, Exchang exchange.Metrics.RequestHeaderSending = ITimingProvider.Default.Instant(); - _logger.Trace(exchange.Id, () => "Begin writing header"); - var headerLength = exchange.Request.Header.WriteHttp11( !exchange.Authority.Secure, buffer, skipNonForwardableHeader: true, writeExtraHeaderField: true, requestClose: false); + exchange.Metrics.RequestHeaderLength = headerLength; + + FluxzyLogEvents.LogRequestSending(_logger, exchange); + // Sending request header await exchange.Connection.WriteStream! .WriteAsync(buffer.Memory.Slice(0, headerLength), cancellationToken) .ConfigureAwait(false); - _logger.Trace(exchange.Id, () => "Header sent"); - exchange.Metrics.TotalSent += headerLength; exchange.Metrics.RequestHeaderSent = ITimingProvider.Default.Instant(); - exchange.Metrics.RequestHeaderLength = headerLength; // Expect: 100-continue path — read any interim/final response from // upstream before streaming the body, otherwise the body-copy below @@ -132,7 +134,7 @@ await ForwardInterimToClient(exchange, 100, cancellationToken) exchange.Metrics.RequestBodySent = exchange.Metrics.RequestHeaderSent; } - _logger.Trace(exchange.Id, () => "Body sent"); + FluxzyLogEvents.LogRequestSent(_logger, exchange, hasEarlyResponseHeader); // Waiting for header block — unless the Expect pre-read already // produced the final response header. @@ -187,7 +189,10 @@ await ForwardInterimToClient(exchange, earlyStatus, cancellationToken) exchange.Response.Header = new ResponseHeader( headerContent, exchange.Authority.Secure, true); - _logger.TraceResponse(exchange); + exchange.Metrics.TotalReceived += headerBlockDetectResult.HeaderLength; + exchange.Metrics.ResponseHeaderLength = headerBlockDetectResult.HeaderLength; + + FluxzyLogEvents.LogResponseHeaderReceived(_logger, exchange); var shouldCloseConnection = exchange.Response.Header.ConnectionCloseRequest; @@ -202,9 +207,7 @@ await ForwardInterimToClient(exchange, earlyStatus, cancellationToken) exchange.Response.Body = Stream.Null; exchange.ExchangeCompletionSource.TrySetResult(shouldCloseConnection || shouldClose); - - _logger.Trace(exchange.Id, () => "No response body"); - + return true; } @@ -232,9 +235,6 @@ await ForwardInterimToClient(exchange, earlyStatus, cancellationToken) ); } - exchange.Metrics.TotalReceived += headerBlockDetectResult.HeaderLength; - exchange.Metrics.ResponseHeaderLength = headerBlockDetectResult.HeaderLength; - ChunkedTransferReadStream? chunkedReadStream = null; if (exchange.Response.Header.ChunkedBody) { @@ -249,7 +249,6 @@ await ForwardInterimToClient(exchange, earlyStatus, cancellationToken) exchange.Response.Body = new MetricsStream(bodyStream, () => { exchange.Metrics.ResponseBodyStart = ITimingProvider.Default.Instant(); - _logger.Trace(exchange.Id, () => "First body bytes read"); }, (endConnection, length) => { exchange.Metrics.ResponseBodyEnd = ITimingProvider.Default.Instant(); @@ -259,13 +258,10 @@ await ForwardInterimToClient(exchange, earlyStatus, cancellationToken) exchange.Response.Trailers = chunkedReadStream.Trailers; exchange.ExchangeCompletionSource.TrySetResult(endConnection); - _logger.Trace(exchange.Id, () => $"Last body bytes end : {length} total bytes"); }, exception => { exchange.Metrics.ResponseBodyEnd = ITimingProvider.Default.Instant(); exchange.ExchangeCompletionSource.SetException(exception); - - _logger.Trace(exchange.Id, () => $"Read error : {exception}"); }, shouldCloseConnection, exchange.Response.Header.ContentLength >= 0 ? exchange.Response.Header.ContentLength : null, diff --git a/src/Fluxzy.Core/Clients/H1Logger.cs b/src/Fluxzy.Core/Clients/H1Logger.cs deleted file mode 100644 index 316b37ce6..000000000 --- a/src/Fluxzy.Core/Clients/H1Logger.cs +++ /dev/null @@ -1,167 +0,0 @@ -// Copyright 2021 - Haga Rakotoharivelo - https://github.com/haga-rak - -using System; -using System.Collections.Generic; -using System.IO; -using System.Linq; -using Fluxzy.Clients.H2; -using Fluxzy.Core; - -namespace Fluxzy.Clients -{ - internal class H1Logger - { - private readonly bool _active; - private readonly string _directory; - - static H1Logger() - { - var hosts = Environment.GetEnvironmentVariable("EnableH1TracingFilterHosts"); - - if (!string.IsNullOrWhiteSpace(hosts)) { - AuthorizedHosts = - hosts.Split(new[] { ",", ";", " " }, StringSplitOptions.RemoveEmptyEntries) - .Select(s => s.Trim()) - .ToList(); - - return; - } - - AuthorizedHosts = null; - } - - public H1Logger(Authority authority, bool? active = null) - { - Authority = authority; - - active ??= string.Equals(Environment.GetEnvironmentVariable("EnableH1Tracing"), - "true", StringComparison.OrdinalIgnoreCase); - - var loggerPath = Environment.ExpandEnvironmentVariables( - Environment.GetEnvironmentVariable("TracingDirectory") - ?? LoggingConstants.DefaultTracingDirectory); - - _active = active.Value; - - if (_active && AuthorizedHosts != null) - - // Check for domain restriction - { - _active = AuthorizedHosts.Any(c => Authority.HostName.EndsWith( - c, StringComparison.OrdinalIgnoreCase)); - } - - _directory = new DirectoryInfo(Path.Combine(loggerPath, "h1")).FullName; - _directory = Path.Combine(_directory, DebugContext.ReferenceString); - - if (_active) { - Directory.CreateDirectory(_directory); - } - } - - public static List? AuthorizedHosts { get; } - - public Authority Authority { get; } - - private void WriteLn(int exchangeId, string message) - { - var fullPath = _directory; - var portString = Authority.Port == 443 ? string.Empty : $"-{Authority.Port:00000}"; - - fullPath = Path.Combine(fullPath, - $"{Authority.HostName}{portString}"); - - Directory.CreateDirectory(fullPath); - - fullPath = Path.Combine(fullPath, $"exId={exchangeId:00000}.txt"); - - lock (string.Intern(fullPath)) { - File.AppendAllText(fullPath, - $"[{ITimingProvider.Default.InstantMillis:000000000}] {message}\r\n"); - } - } - - public void TraceResponse(Exchange exchange, bool full = false) - { - if (!_active) - return; - - var firstLine = full - ? exchange.Response.Header?.GetHttp11Header().ToString() - : exchange.Response.Header?.GetHttp11Header().ToString().Split("\r\n").First(); - - Trace(exchange.Id, "Response : " + firstLine); - } - - public void Trace(int exchangeId, string message) - { - if (!_active) - return; - - WriteLn(exchangeId, message); - } - - public void Trace( - int exchangeId, - Func sendMessage) - { - if (!_active) - return; - - Trace(exchangeId, sendMessage()); - } - - public void Trace(Exchange exchange, string preMessage, Exception? ex = null) - { - if (!_active) - return; - - Trace(exchange, preMessage + (ex == null ? string.Empty : ex.ToString())); - } - - public void Trace( - StreamWorker streamWorker, - Exchange exchange, - string preMessage) - { - if (!_active) - return; - - Trace(exchange, preMessage); - } - - public void Trace( - Exchange exchange, - Func sendMessage) - { - if (!_active) - return; - - Trace(exchange, sendMessage()); - } - - public void Trace( - Exchange exchange, - string preMessage) - { - if (!_active) - return; - - var method = exchange.Request.Header[":method".AsMemory()].First().Value.ToString(); - var path = exchange.Request.Header[":path".AsMemory()].First().Value.ToString(); - - var maxLength = 30; - - if (path.Length > maxLength) - path = "..." + path.Substring(path.Length - (maxLength - 3), maxLength - 3); - - var message = - $"{method.PadRight(6, ' ')} - " + - $"({path}) - " + - $"Cid = {exchange.Connection?.Id ?? 0} " + - $" - {preMessage}"; - - WriteLn(exchange.Id, message); - } - } -} diff --git a/src/Fluxzy.Core/Clients/H2/Encoder/HPack/HPackDecodingDynamicTable.cs b/src/Fluxzy.Core/Clients/H2/Encoder/HPack/HPackDecodingDynamicTable.cs index 9b79f46de..fec4af160 100644 --- a/src/Fluxzy.Core/Clients/H2/Encoder/HPack/HPackDecodingDynamicTable.cs +++ b/src/Fluxzy.Core/Clients/H2/Encoder/HPack/HPackDecodingDynamicTable.cs @@ -20,9 +20,6 @@ public HPackDecodingDynamicTable(int initialSize) _currentMaxSize = initialSize; _ring = new HeaderField[Math.Max(16, initialSize / 32)]; } - - internal H2Logger? Logger { get; set; } - private void EvictUntil(int toBeRemovedSize) { var evictedSize = 0; diff --git a/src/Fluxzy.Core/Clients/H2/Encoder/HPackDecoder.cs b/src/Fluxzy.Core/Clients/H2/Encoder/HPackDecoder.cs index 983a1b39b..b6d2ec1a5 100644 --- a/src/Fluxzy.Core/Clients/H2/Encoder/HPackDecoder.cs +++ b/src/Fluxzy.Core/Clients/H2/Encoder/HPackDecoder.cs @@ -42,8 +42,6 @@ internal HPackDecoder( _memoryProvider = memoryProvider ?? ArrayPoolMemoryProvider.Default; } - internal H2Logger? Logger { get; set; } - public DecodingContext Context { get; } public void Dispose() diff --git a/src/Fluxzy.Core/Clients/H2/H2ConnectionPool.cs b/src/Fluxzy.Core/Clients/H2/H2ConnectionPool.cs index a2227b4e2..6b6567b22 100644 --- a/src/Fluxzy.Core/Clients/H2/H2ConnectionPool.cs +++ b/src/Fluxzy.Core/Clients/H2/H2ConnectionPool.cs @@ -13,8 +13,11 @@ using Fluxzy.Clients.H2.Encoder.Utils; using Fluxzy.Clients.H2.Frames; using Fluxzy.Core; +using Fluxzy.Logging; using Fluxzy.Misc; using Fluxzy.Misc.ResizableBuffers; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Fluxzy.Clients.H2 { @@ -26,7 +29,6 @@ public class H2ConnectionPool : IHttpConnectionPool private readonly Connection _connection; private readonly CancellationToken _connectionToken; - private readonly H2Logger _logger; private readonly Action? _onConnectionFaulted; private readonly SemaphoreSlim _streamCreationLock = new(1); @@ -73,7 +75,8 @@ public H2ConnectionPool( Stream baseStream, H2StreamSetting setting, Authority authority, - Connection connection, Action onConnectionFaulted) + Connection connection, Action onConnectionFaulted, + ILogger? logger = null) { Id = Interlocked.Increment(ref _connectionIdCounter); @@ -82,10 +85,9 @@ public H2ConnectionPool( Setting = setting; _connection = connection; _onConnectionFaulted = onConnectionFaulted; - _logger = new H2Logger(Authority, Id); _connectionToken = _connectionCancellationTokenSource.Token; - _overallWindowSizeHolder = new WindowSizeHolder(_logger, Setting.OverallWindowSize, 0); + _overallWindowSizeHolder = new WindowSizeHolder(Setting.OverallWindowSize, 0); _writerChannel = Channel.CreateUnbounded(new UnboundedChannelOptions { @@ -103,9 +105,10 @@ public H2ConnectionPool( _streamPool = new StreamPool( new StreamContext( - Id, authority, setting, _logger, + Id, authority, setting, headerEncoder, UpStreamChannel, - _overallWindowSizeHolder)); + _overallWindowSizeHolder, + logger ?? NullLogger.Instance)); } public int Id { get; } @@ -129,7 +132,7 @@ public void Init() _initDone = true; //_baseStream.Write(Preface); - SettingHelper.WriteWelcomeSettings(H2Constants.Preface, _baseStream, Setting, _logger); + SettingHelper.WriteWelcomeSettings(H2Constants.Preface, _baseStream, Setting); _innerReadTask = InternalReadLoop(_connectionToken); _innerWriteRun = InternalWriteLoop(_connectionToken); @@ -188,7 +191,6 @@ internal bool TryIdleTeardown() if (_streamPool.ActiveStreamCount != 0) return false; OnLoopEnd(null, true); - _logger.Trace(0, () => "Drain complete. Connection closed."); return true; } finally { @@ -224,8 +226,6 @@ internal bool TryIdleTeardown() OnLoopEnd(null, true); - _logger.Trace(0, () => "IDLE timeout. Connection closed."); - return true; } finally { @@ -271,16 +271,11 @@ public async ValueTask Send( Interlocked.Increment(ref TotalRequest); try { - _logger.Trace(exchange, "Send start"); - exchange.Connection = _connection; await InternalSend(exchange, buffer, cancellationToken).ConfigureAwait(false); - - _logger.Trace(exchange, "Response header received"); } catch (Exception ex) { - _logger.Trace(exchange, "Send on error " + ex); if (ex is OperationCanceledException opex && cancellationToken != default @@ -321,7 +316,6 @@ public async ValueTask DisposeAsync() // without observing a cancelled CTS. _idleTimer?.Dispose(); - _logger.Trace(0, () => "Disposed"); _connectionCancellationTokenSource?.Cancel(); _connectionCancellationTokenSource?.Dispose(); @@ -430,9 +424,7 @@ private void OnLoopEnd(Exception? ex, bool releaseChannelItems) _complete = true; // End the connection. This operation is idempotent. - - _logger.Trace(0, "Cleanup start " + ex); - + // IMPORTANT: drive ALL of our own internal cleanup BEFORE notifying the // fault callback. The callback (in PoolBuilder.OnConnectionFaulted) may // synchronously start tearing the pool down via DisposeAsync, and the @@ -475,8 +467,6 @@ private void OnLoopEnd(Exception? ex, bool releaseChannelItems) // disposal via ObserveDisposal. if (Interlocked.CompareExchange(ref _faultCallbackFired, 1, 0) == 0) _onConnectionFaulted?.Invoke(this); - - _logger.Trace(0, "Cleanup end"); } private async Task InternalWriteLoop(CancellationToken token) @@ -525,9 +515,6 @@ private async Task InternalWriteLoop(CancellationToken token) .Write(memoryBuffer.Span); memoryBuffer = memoryBuffer.Slice(13); - - _logger.OutgoingWindowUpdate(writeTask.WindowUpdateSize, - writeTask.StreamIdentifier); } await _baseStream.WriteAsync(heapBuffer, 0, bufferLength, token).ConfigureAwait(false); @@ -572,7 +559,6 @@ await _baseStream .ConfigureAwait(false); for (var i = 0; i < otherTasks.Count; i++) { - _logger.OutgoingFrame(otherTasks[i].BufferBytes); otherTasks[i].OnComplete(null); } } @@ -627,18 +613,13 @@ private async Task InternalReadLoop(CancellationToken token) try { while (!token.IsCancellationRequested) { - _logger.TraceDeep(0, () => "1"); - var frame = await reader.ReadNextFrameAsync(token).ConfigureAwait(false); if (ProcessNewFrame(frame)) break; } - - _logger.TraceDeep(0, () => "Natural death"); } catch (OperationCanceledException) { - _logger.TraceDeep(0, () => "OperationCanceledException death"); } catch (Exception ex) { // Surface the cause verbatim. Previously this was gated on a @@ -654,17 +635,11 @@ private async Task InternalReadLoop(CancellationToken token) private bool ProcessNewFrame(H2FrameReadResult frame) { - _logger.TraceDeep(0, () => "2"); - if (frame.IsEmpty) return true; - - _logger.TraceDeep(0, () => "3"); - + _lastActivity = ITimingProvider.Default.Instant(); - - _logger.IncomingFrame(ref frame); - + _streamPool.TryGetExistingActiveStream(frame.StreamIdentifier, out var activeStream); if (frame.BodyType == H2FrameType.Settings) { @@ -673,7 +648,6 @@ private bool ProcessNewFrame(H2FrameReadResult frame) while (frame.TryReadNextSetting(out var settingFrame, ref indexer)) { - _logger.IncomingSetting(ref settingFrame); var needAck = H2Helper.ProcessIncomingSettingFrame(Setting, ref settingFrame); if (settingFrame.SettingIdentifier == SettingIdentifier.SettingsInitialWindowSize) { @@ -682,8 +656,6 @@ private bool ProcessNewFrame(H2FrameReadResult frame) } sendAck = sendAck || needAck; - - _logger.TraceDeep(0, () => "4"); } if (sendAck) { @@ -698,8 +670,6 @@ private bool ProcessNewFrame(H2FrameReadResult frame) } if (frame.BodyType == H2FrameType.Priority) { - _logger.TraceDeep(0, () => "5"); - if (activeStream == null) return false; @@ -709,8 +679,6 @@ private bool ProcessNewFrame(H2FrameReadResult frame) } if (frame.BodyType == H2FrameType.Headers) { - _logger.TraceDeep(0, () => "6"); - if (activeStream == null) // TODO : Notify stream error, stream already closed @@ -724,8 +692,6 @@ private bool ProcessNewFrame(H2FrameReadResult frame) } if (frame.BodyType == H2FrameType.Continuation) { - _logger.TraceDeep(0, () => "7"); - if (activeStream == null) // TODO : Notify stream error, stream already closed @@ -739,25 +705,17 @@ private bool ProcessNewFrame(H2FrameReadResult frame) } if (frame.BodyType == H2FrameType.Data) { - _logger.TraceDeep(0, () => "8 : "); - if (activeStream == null) return false; - - _logger.TraceDeep(0, () => "8 : " + activeStream.StreamIdentifier); - + activeStream.ReceiveBodyFragmentFromConnection( frame.GetDataFrame().Buffer, frame.Flags.HasFlag(HeaderFlags.EndStream)); - _logger.TraceDeep(0, () => "8 1 : " + activeStream.StreamIdentifier); - return false; } if (frame.BodyType == H2FrameType.RstStream) { - _logger.TraceDeep(0, () => "9"); - if (activeStream == null) return false; @@ -767,8 +725,6 @@ private bool ProcessNewFrame(H2FrameReadResult frame) } if (frame.BodyType == H2FrameType.WindowUpdate) { - _logger.TraceDeep(0, () => "10"); - var windowSizeIncrement = frame.GetWindowUpdateFrame().WindowSizeIncrement; if (activeStream == null) { @@ -783,16 +739,12 @@ private bool ProcessNewFrame(H2FrameReadResult frame) } if (frame.BodyType == H2FrameType.Ping) { - _logger.TraceDeep(0, () => "11"); - EmitPing(frame.GetPingFrame().OpaqueData); return false; } if (frame.BodyType == H2FrameType.Goaway) { - _logger.TraceDeep(0, () => "12"); - var goAwayFrame = frame.GetGoAwayFrame(); OnGoAway(ref goAwayFrame); @@ -866,6 +818,8 @@ await _streamPool.CreateNewStreamProcessing( if (!hasRequestBody) { exchange.Metrics.RequestBodySent = exchange.Metrics.RequestHeaderSent; + FluxzyLogEvents.LogRequestSent( + _streamPool.Context.Logger, exchange, earlyResponse: false); } // Run request body upload and response processing concurrently. diff --git a/src/Fluxzy.Core/Clients/H2/SettingHelper.cs b/src/Fluxzy.Core/Clients/H2/SettingHelper.cs index 7ef41e508..eade1508f 100644 --- a/src/Fluxzy.Core/Clients/H2/SettingHelper.cs +++ b/src/Fluxzy.Core/Clients/H2/SettingHelper.cs @@ -10,7 +10,7 @@ namespace Fluxzy.Clients.H2 { internal static class SettingHelper { - private static int WriteStartupSetting(Span buffer, H2StreamSetting h2Setting, H2Logger logger) + private static int WriteStartupSetting(Span buffer, H2StreamSetting h2Setting) { var written = 0; var headerCount = 9; @@ -20,11 +20,8 @@ private static int WriteStartupSetting(Span buffer, H2StreamSetting h2Sett var totalSettingCount = 0; foreach (var (settingIdentifier, value) in h2Setting.GetAnnouncementSettings()) { - - var currentSetting = new SettingFrame(settingIdentifier, value); written += SettingFrame.WriteMultipleBody(buffer.Slice(written + headerCount), settingIdentifier, value); totalSettingCount++; - logger.OutgoingSetting(ref currentSetting); } // 5 bytes header @@ -33,7 +30,7 @@ private static int WriteStartupSetting(Span buffer, H2StreamSetting h2Sett return written; } - public static void WriteWelcomeSettings(byte [] preface, Stream innerStream, H2StreamSetting h2Setting, H2Logger logger) + public static void WriteWelcomeSettings(byte [] preface, Stream innerStream, H2StreamSetting h2Setting) { Span settingBuffer = stackalloc byte[512]; @@ -41,7 +38,7 @@ public static void WriteWelcomeSettings(byte [] preface, Stream innerStream, H2S preface.AsSpan().CopyTo(settingBuffer); written += preface.Length; - written += WriteStartupSetting(settingBuffer.Slice(written), h2Setting, logger); + written += WriteStartupSetting(settingBuffer.Slice(written), h2Setting); var windowSizeAnnounced = h2Setting.Local.WindowSize - 65535; @@ -66,13 +63,12 @@ public static async Task WriteAckSetting(Stream innerStream) } } - public static void WriteAck(Stream innerStream, H2Logger logger) + public static void WriteAck(Stream innerStream) { Span settingBuffer = stackalloc byte[80]; var settingFrame = new SettingFrame(true); var written = settingFrame.Write(settingBuffer); - logger.OutgoingSetting(ref settingFrame); innerStream.Write(settingBuffer.Slice(0, written)); } } diff --git a/src/Fluxzy.Core/Clients/H2/StreamContext.cs b/src/Fluxzy.Core/Clients/H2/StreamContext.cs index 19f6858b9..fddfef7fa 100644 --- a/src/Fluxzy.Core/Clients/H2/StreamContext.cs +++ b/src/Fluxzy.Core/Clients/H2/StreamContext.cs @@ -1,6 +1,8 @@ // Copyright 2021 - Haga Rakotoharivelo - https://github.com/haga-rak using Fluxzy.Core; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Fluxzy.Clients.H2 { @@ -10,18 +12,18 @@ public StreamContext( int connectionId, Authority authority, H2StreamSetting setting, - H2Logger logger, IHeaderEncoder headerEncoder, UpStreamChannel upStreamChannel, - WindowSizeHolder overallWindowSizeHolder) + WindowSizeHolder overallWindowSizeHolder, + ILogger? logger = null) { ConnectionId = connectionId; Authority = authority; Setting = setting; - Logger = logger; HeaderEncoder = headerEncoder; UpStreamChannel = upStreamChannel; OverallWindowSizeHolder = overallWindowSizeHolder; + Logger = logger ?? NullLogger.Instance; } public int ConnectionId { get; } @@ -30,12 +32,12 @@ public StreamContext( public H2StreamSetting Setting { get; } - public H2Logger Logger { get; } - public IHeaderEncoder HeaderEncoder { get; } public UpStreamChannel UpStreamChannel { get; } public WindowSizeHolder OverallWindowSizeHolder { get; } + + public ILogger Logger { get; } } } diff --git a/src/Fluxzy.Core/Clients/H2/StreamPool.cs b/src/Fluxzy.Core/Clients/H2/StreamPool.cs index 2586eef42..1839927cb 100644 --- a/src/Fluxzy.Core/Clients/H2/StreamPool.cs +++ b/src/Fluxzy.Core/Clients/H2/StreamPool.cs @@ -80,8 +80,6 @@ private async ValueTask CreateActiveStreamAsync( _runningStreams[streamId] = activeStream; - Context.Logger.Trace(exchange, "Affecting streamIdentifier", streamIdentifier: streamId); - return activeStream; } diff --git a/src/Fluxzy.Core/Clients/H2/StreamWorker.cs b/src/Fluxzy.Core/Clients/H2/StreamWorker.cs index 1ea93d53c..50b9eced0 100644 --- a/src/Fluxzy.Core/Clients/H2/StreamWorker.cs +++ b/src/Fluxzy.Core/Clients/H2/StreamWorker.cs @@ -8,6 +8,7 @@ using Fluxzy.Clients.H2.Encoder; using Fluxzy.Clients.H2.Frames; using Fluxzy.Core; +using Fluxzy.Logging; using Fluxzy.Misc.ResizableBuffers; namespace Fluxzy.Clients.H2 @@ -17,9 +18,7 @@ internal sealed class StreamWorker : IDisposable private readonly Exchange _exchange; private readonly SemaphoreSlim _headerReceivedSemaphore = new(0, 1); - - private readonly H2Logger _logger; - + private readonly Pipe _pipeResponseBody; private readonly CancellationTokenSource _resetTokenSource; @@ -51,12 +50,9 @@ public StreamWorker( _exchange = exchange; _resetTokenSource = resetTokenSource; - RemoteWindowSize = new WindowSizeHolder(parent.Context.Logger, - parent.Context.Setting.Remote.WindowSize, + RemoteWindowSize = new WindowSizeHolder(parent.Context.Setting.Remote.WindowSize, streamIdentifier); - - _logger = parent.Context.Logger; - + _pipeResponseBody = new Pipe(new PipeOptions( pool: MemoryPool.Shared, readerScheduler: PipeScheduler.ThreadPool, @@ -83,9 +79,7 @@ public StreamWorker( public void Dispose() { _disposed = true; - - _logger.Trace(StreamIdentifier, ".... disposing"); - + RemoteWindowSize?.Dispose(); if (_headerBuffer != null) { @@ -100,8 +94,6 @@ public void Dispose() catch (SemaphoreFullException) { // We do nothing here } - - _logger.Trace(StreamIdentifier, ".... disposed"); } private async ValueTask BookWindowSize(int requestedBodyLength, CancellationToken cancellationToken) @@ -200,8 +192,6 @@ public void ResetRequest(H2ErrorCode errorCode) if (_exchange.Response.Header != null) value += _exchange.Response.Header.GetHttp11Header().ToString(); - - _logger.Trace(StreamIdentifier, $"Receive RST : {errorCode} from server.\r\n{value}"); } _exchange.ExchangeCompletionSource @@ -230,6 +220,9 @@ public Task EnqueueRequestHeader(Exchange exchange, RsBuffer buffer, Cancellatio buffer, endStream); exchange.Metrics.RequestHeaderSending = ITimingProvider.Default.Instant(); + exchange.Metrics.RequestHeaderLength = readyToBeSent.Length; + + FluxzyLogEvents.LogRequestSending(Parent.Context.Logger, exchange); var writeHeaderTask = new WriteTask(H2FrameType.Headers, StreamIdentifier, StreamPriority, StreamDependency, readyToBeSent); @@ -238,8 +231,6 @@ public Task EnqueueRequestHeader(Exchange exchange, RsBuffer buffer, Cancellatio return writeHeaderTask.DoneTask .ContinueWith(t => { - exchange.Metrics.RequestHeaderLength = readyToBeSent.Length; - return _exchange.Metrics.TotalSent += readyToBeSent.Length; }, token); } @@ -254,6 +245,7 @@ public async ValueTask ProcessRequestBody(Exchange exchange, RsBuffer buffer, Ca // which would otherwise trip the loop's "!CanSeek" entry condition. if (_headerEndedStream) { exchange.Metrics.RequestBodySent = ITimingProvider.Default.Instant(); + FluxzyLogEvents.LogRequestSent(Parent.Context.Logger, exchange, earlyResponse: false); return; } @@ -310,6 +302,7 @@ public async ValueTask ProcessRequestBody(Exchange exchange, RsBuffer buffer, Ca if (dataFramePayloadLength == 0 || endStream) { exchange.Metrics.RequestBodySent = ITimingProvider.Default.Instant(); + FluxzyLogEvents.LogRequestSent(Parent.Context.Logger, exchange, earlyResponse: false); return; } @@ -406,7 +399,7 @@ private void ReceiveHeaderFragmentFromConnection( return; // We wait for more header and ignore 103 } - _logger.TraceResponse(this, _exchange); + FluxzyLogEvents.LogResponseHeaderReceived(Parent.Context.Logger, _exchange); if (DebugContext.InsertFluxzyMetricsOnResponseHeader) { var headerName = "fluxzy-h2-debug"; @@ -420,9 +413,7 @@ private void ReceiveHeaderFragmentFromConnection( _responseHeadersComplete = true; _totalHeaderReceived = 0; // Reset for possible trailer accumulation - - _logger.Trace(StreamIdentifier, "Releasing semaphore"); - + _headerReceivedSemaphore.Release(); } } @@ -442,10 +433,7 @@ private void ReceiveTrailerFragmentFromConnection( _headerBuffer.AsSpan(0, _totalHeaderReceived)); _exchange.Response.Trailers = trailerFields; - - _logger.Trace(StreamIdentifier, - () => $"Response trailers received: {trailerFields.Count} fields"); - + // Trailers always signal end of stream — complete the body pipe and exchange if (_exchange.Metrics.ResponseBodyEnd == default) _exchange.Metrics.ResponseBodyEnd = ITimingProvider.Default.Instant(); @@ -465,16 +453,10 @@ private void ReceiveTrailerFragmentFromConnection( public async ValueTask ProcessResponse(CancellationToken cancellationToken, H2ConnectionPool cp) { try { - _logger.Trace(StreamIdentifier, "Before semaphore "); - if (!cancellationToken.IsCancellationRequested) await _headerReceivedSemaphore.WaitAsync(cancellationToken).ConfigureAwait(false); - - _logger.Trace(StreamIdentifier, "Acquire semaphore "); } catch (OperationCanceledException) { - _logger.Trace(StreamIdentifier, $"Received no header, cancelled by caller {StreamIdentifier}"); - if (_abandonedByGoAway) { Parent.NotifyDispose(this); throw new ConnectionCloseException( @@ -510,31 +492,20 @@ public void ReceiveBodyFragmentFromConnection(ReadOnlyMemory buffer, bool } _totalBodyReceived += buffer.Length; - - _logger.TraceDeep(StreamIdentifier, () => "a - 1"); - + if (_firstBodyFragment) { _exchange.Metrics.ResponseBodyStart = ITimingProvider.Default.Instant(); _firstBodyFragment = false; - - _logger.Trace(_exchange, StreamIdentifier, - () => "First body block received"); } - _logger.TraceDeep(StreamIdentifier, () => "a - 2"); OnDataConsumedByCaller(buffer.Length); if (endStream) { - _logger.Trace(_exchange, StreamIdentifier, - () => "Total body received : " + _totalBodyReceived); - _exchange.Metrics.ResponseBodyEnd = ITimingProvider.Default.Instant(); } _exchange.Metrics.TotalReceived += buffer.Length; - _logger.TraceDeep(StreamIdentifier, () => "a - 3"); - var cancelled = false; try { @@ -544,31 +515,21 @@ public void ReceiveBodyFragmentFromConnection(ReadOnlyMemory buffer, bool catch { cancelled = true; } - - _logger.TraceDeep(StreamIdentifier, () => "a - 4"); - + var shouldEnd = endStream || cancelled; if (shouldEnd) { if (_exchange.Metrics.ResponseBodyEnd == default) _exchange.Metrics.ResponseBodyEnd = ITimingProvider.Default.Instant(); - _logger.Trace(_exchange, StreamIdentifier, - () => "End"); - if (!cancelled) _pipeResponseBody.Writer.Complete(); - - _logger.TraceDeep(StreamIdentifier, () => "a - 5"); - + _exchange.ExchangeCompletionSource.TrySetResult(false); // Give a chance for semaphores to released before disposed // await Task.Yield(); - - _logger.TraceDeep(StreamIdentifier, () => "a - 6"); - Parent.NotifyDispose(this); } } diff --git a/src/Fluxzy.Core/Clients/H2/WindowSizeHolder.cs b/src/Fluxzy.Core/Clients/H2/WindowSizeHolder.cs index 073a05999..3093024ef 100644 --- a/src/Fluxzy.Core/Clients/H2/WindowSizeHolder.cs +++ b/src/Fluxzy.Core/Clients/H2/WindowSizeHolder.cs @@ -10,8 +10,6 @@ namespace Fluxzy.Clients.H2 { internal sealed class WindowSizeHolder : IDisposable { - private readonly H2Logger _logger; - // Mutex for the waiter queue only. The value field uses lock-free CAS. private readonly object _sync = new(); @@ -22,11 +20,9 @@ internal sealed class WindowSizeHolder : IDisposable private int _availableWindowSize; public WindowSizeHolder( - H2Logger logger, int availableWindowSize, int streamIdentifier) { - _logger = logger ?? throw new ArgumentNullException(nameof(logger)); _availableWindowSize = availableWindowSize; StreamIdentifier = streamIdentifier; InitialWindowSize = availableWindowSize; @@ -60,8 +56,6 @@ public void UpdateInitialWindowSize(int newInitialWindowSize) /// public void UpdateWindowSize(int windowSizeIncrement) { - _logger.Trace(this, windowSizeIncrement); - // Lock-free CAS update of the value. int before, after; while (true) @@ -138,8 +132,6 @@ public async ValueTask BookWindowSize(int requestedLength, CancellationToke var grant = Math.Min(requestedLength, current); if (Interlocked.CompareExchange(ref _availableWindowSize, current - grant, current) == current) { - _logger.Trace(this, -grant); - // Cascade: if window remains after our booking, wake the next waiter. if (current - grant > 0) WakeOneWaiter(); @@ -164,8 +156,6 @@ public async ValueTask BookWindowSize(int requestedLength, CancellationToke var grant = Math.Min(requestedLength, current); if (Interlocked.CompareExchange(ref _availableWindowSize, current - grant, current) == current) { - _logger.Trace(this, -grant); - if (current - grant > 0) WakeOneWaiter(); diff --git a/src/Fluxzy.Core/Clients/H2Logger.cs b/src/Fluxzy.Core/Clients/H2Logger.cs deleted file mode 100644 index 188a4795d..000000000 --- a/src/Fluxzy.Core/Clients/H2Logger.cs +++ /dev/null @@ -1,394 +0,0 @@ -// Copyright 2021 - Haga Rakotoharivelo - https://github.com/haga-rak - -using System; -using System.Collections.Generic; -using System.IO; -using System.Linq; -using System.Text; -using Fluxzy.Clients.H2; -using Fluxzy.Clients.H2.Frames; -using Fluxzy.Core; - -namespace Fluxzy.Clients -{ - /// - /// Utility for tracing H2 Connection - /// - internal class H2Logger - { - private static readonly string? _directory; - - private static readonly string loggerPath = Environment.ExpandEnvironmentVariables( - Environment.GetEnvironmentVariable("TracingDirectory") - ?? LoggingConstants.DefaultTracingDirectory); - - private readonly bool _active; - - static H2Logger() - { - if (!DebugContext.IsH2TracingEnabled) - return; - - _directory = new DirectoryInfo(Path.Combine(loggerPath, "h2")).FullName; - _directory = Path.Combine(_directory, DebugContext.ReferenceString); - - - var hosts = Environment.GetEnvironmentVariable("EnableH2TracingFilterHosts"); - - if (!string.IsNullOrWhiteSpace(hosts)) { - AuthorizedHosts = - hosts.Split(new[] { ",", ";", " " }, StringSplitOptions.RemoveEmptyEntries) - .Select(s => s.Trim()) - .ToList(); - - return; - } - - Directory.CreateDirectory(_directory); - AuthorizedHosts = null; - } - - public H2Logger(Authority authority, int connectionId, bool? active = null) - { - Authority = authority; - ConnectionId = connectionId; - - active ??= DebugContext.IsH2TracingEnabled; - - _active = active.Value; - - if (_active && AuthorizedHosts != null) - - // Check for domain restriction - { - _active = AuthorizedHosts.Any(c => Authority.HostName.EndsWith( - c, StringComparison.OrdinalIgnoreCase)); - } - } - - public static List? AuthorizedHosts { get; } - - public Authority Authority { get; } - - public int ConnectionId { get; } - - private void WriteLn(int streamIdentifier, string message) - { - if (_directory == null) - return; - - var fullPath = _directory; - var portString = Authority.Port == 443 ? string.Empty : $"-{Authority.Port:00000}"; - - fullPath = Path.Combine(fullPath, - $"{Authority.HostName}{portString}"); - - Directory.CreateDirectory(fullPath); - - fullPath = Path.Combine(fullPath, $"cId={ConnectionId:00000}-sId={streamIdentifier:00000}.txt"); - - lock (string.Intern(fullPath)) { - File.AppendAllText(fullPath, - $"[{ITimingProvider.Default.InstantMillis:000000000}] {message}\r\n"); - } - } - - private void WriteLnHPack(int streamIdentifier, string message) - { - var fullPath = _directory!; - var portString = Authority.Port == 443 ? string.Empty : $"-{Authority.Port:00000}"; - - fullPath = Path.Combine(fullPath, - $"{Authority.HostName}{portString}"); - - Directory.CreateDirectory(fullPath); - - fullPath = Path.Combine(fullPath, $"cId={ConnectionId:00000}-hpack.txt"); - - lock (string.Intern(fullPath)) { - File.AppendAllText(fullPath, - $"[{ITimingProvider.Default.InstantMillis:000000000}] ({streamIdentifier:00000}) - {message}\r\n"); - } - } - - private static string GetFrameExtraMessage(ref H2FrameReadResult frame) - { - switch (frame.BodyType) { - case H2FrameType.Data: { - var innerFrame = frame.GetDataFrame(); - - return $"Length = {innerFrame.BodyLength}, EndStream = {innerFrame.EndStream}"; - } - - case H2FrameType.Headers: { - var innerFrame = frame.GetHeadersFrame(); - - return - $"Length = {innerFrame.BodyLength}, EndHeaders = {innerFrame.EndHeaders}, EndStream = {innerFrame.EndStream}"; - } - - case H2FrameType.Priority: { - var innerFrame = frame.GetPriorityFrame(); - - return - $"Exclusive = {innerFrame.Exclusive}, StreamDependency = {innerFrame.StreamDependency}, Weight = {innerFrame.Weight}"; - } - - case H2FrameType.RstStream: { - var innerFrame = frame.GetRstStreamFrame(); - - return $"ErrorCode = {innerFrame.ErrorCode}"; - } - - case H2FrameType.Settings: { - var builder = new StringBuilder(); - var index = 0; - - while (frame.TryReadNextSetting(out var innerFrame, ref index)) { - builder.Append( - $"Ack = {innerFrame.Ack}, SettingIdentifier = {innerFrame.SettingIdentifier}, Value = {innerFrame.Value}, "); - } - - return builder.ToString(); - } - - case H2FrameType.PushPromise: { - return ""; - } - - case H2FrameType.Ping: { - return ""; - } - - case H2FrameType.Goaway: { - var innerFrame = frame.GetGoAwayFrame(); - - return $"ErrorCode = {innerFrame.ErrorCode}, LastStreamId = {innerFrame.LastStreamId}"; - } - - case H2FrameType.WindowUpdate: { - var innerFrame = frame.GetWindowUpdateFrame(); - - return $"WindowSizeIncrement = {innerFrame.WindowSizeIncrement}"; - } - - case H2FrameType.Continuation: { - var innerFrame = frame.GetContinuationFrame(); - - return $"Length = {innerFrame.BodyLength}, EndHeaders = {innerFrame.EndHeaders}"; - } - - default: - return ""; - } - } - - public void IncomingFrame(ref H2FrameReadResult frame) - { - if (!_active) - return; - - var message = - "RCV <== " + - $"Type = {frame.BodyType}, " + - $"Flags = {frame.Flags}, "; - - message += GetFrameExtraMessage(ref frame); - - WriteLn(frame.StreamIdentifier, message); - } - - public void OutgoingFrame(ref H2FrameReadResult frame) - { - if (!_active) - return; - - var message = - "SNT ==> " + - $"Type = {frame.BodyType}, " + - $"Flags = {frame.Flags}, "; - - message += GetFrameExtraMessage(ref frame); - - WriteLn(frame.StreamIdentifier, message); - } - - public void OutgoingFrame(ReadOnlyMemory buffer) - { - if (!_active) - return; - - var frame = H2FrameReader.ReadFrame(ref buffer); - - OutgoingFrame(ref frame); - } - - public void OutgoingWindowUpdate(int value, int streamIdentifier) - { - if (!_active) - return; - - var message = - "SNT ==> " + - $"Type = {H2FrameType.WindowUpdate}, "; - - message += $"WindowSizeIncrement = {value}"; - ; - - WriteLn(streamIdentifier, message); - } - - public void Trace(int streamId, string message) - { - if (!_active) - return; - - WriteLn(streamId, message); - } - - public void TraceH(int streamId, Func message) - { - if (!_active) - return; - - WriteLnHPack(streamId, message()); - } - - public void Trace(int streamId, Func messageString) - { - if (!_active) - return; - - WriteLn(streamId, messageString()); - } - - public void TraceDeep(int streamId, Func messageString) - { - if (!_active || true) - return; - - WriteLn(streamId, messageString()); - } - - public void TraceDeep(int streamId, string messageString) - { - if (!_active) - return; - - WriteLn(streamId, messageString); - } - - public void Trace(Exchange exchange, string preMessage, Exception? ex = null, int streamIdentifier = 0) - { - if (!_active) - return; - - Trace(exchange, streamIdentifier, preMessage + (ex == null ? string.Empty : ex.ToString())); - } - - public void Trace( - StreamWorker streamWorker, - Exchange exchange, - string preMessage) - { - if (!_active) - return; - - Trace(exchange, streamWorker.StreamIdentifier, preMessage); - } - - public void TraceResponse( - StreamWorker streamWorker, - Exchange exchange) - { - if (!_active) - return; - - var firstLine = exchange.Response.Header?.GetHttp11Header().ToString().Split("\r\n").First(); - - Trace(exchange, streamWorker.StreamIdentifier, "Response : " + firstLine); - } - - public void IncomingSetting(ref SettingFrame settingFrame) - { - if (!_active) - return; - - var message = - "RCV <== "; - - message += - $"Ack = {settingFrame.Ack}, SettingIdentifier = {settingFrame.SettingIdentifier}, Value = {settingFrame.Value}"; - - WriteLn(0, message); - } - - public void OutgoingSetting(ref SettingFrame settingFrame) - { - if (!_active) - return; - - var message = - "SNT ==> "; - - message += - $"Ack = {settingFrame.Ack}, SettingIdentifier = {settingFrame.SettingIdentifier}, Value = {settingFrame.Value}"; - - WriteLn(0, message); - } - - public void Trace( - Exchange exchange, - int streamId, - Func sendMessage) - { - if (!_active) - return; - - Trace(exchange, streamId, sendMessage()); - } - - public void Trace( - Exchange exchange, - int streamId, - string preMessage) - { - if (!_active) - return; - - var method = exchange.Request.Header[":method".AsMemory()].First().Value.ToString(); - var path = exchange.Request.Header[":path".AsMemory()].First().Value.ToString(); - - var maxLength = 30; - - if (path.Length > maxLength) - path = "..." + path.Substring(path.Length - (maxLength - 3), maxLength - 3); - - var message = - $"{method.PadRight(6, ' ')} - " + - $"({path}) - " + - $"Sid = {streamId} " + - $" - {preMessage}"; - - WriteLn(streamId, message); - } - - public void Trace( - WindowSizeHolder holder, - int windowSizeIncrement) - { - if (!_active) - return; - - var message = - "Window Update - " + - $"Before = {holder.AvailableWindowSize} - " + - $"Value = {windowSizeIncrement} - " + - $"After = {holder.AvailableWindowSize + windowSizeIncrement} - "; - - //$"Sid = {holder.StreamIdentifier} " + - - WriteLn(holder.StreamIdentifier, message); - } - } -} diff --git a/src/Fluxzy.Core/Clients/IRemoteConnectionBuilder.cs b/src/Fluxzy.Core/Clients/IRemoteConnectionBuilder.cs index 312baaa75..65e5a3a9c 100644 --- a/src/Fluxzy.Core/Clients/IRemoteConnectionBuilder.cs +++ b/src/Fluxzy.Core/Clients/IRemoteConnectionBuilder.cs @@ -8,6 +8,7 @@ using System.Threading.Tasks; using Fluxzy.Clients.Ssl; using Fluxzy.Core; +using Fluxzy.Logging; using Fluxzy.Misc.Streams; namespace Fluxzy.Clients @@ -98,6 +99,12 @@ public async ValueTask OpenConnectionToRemote( if (!exchange.Authority.Secure || exchange.Context.BlindMode) { exchange.Connection.ReadStream = exchange.Connection.WriteStream = newlyOpenedStream; + exchange.Connection.HttpVersion ??= "HTTP/1.1"; + + FluxzyLogEvents.LogConnectionOpened( + setting.GetLogger(), + exchange.Connection, + proxyConfiguration != null); return new RemoteConnectionResult(RemoteConnectionResultType.Unknown, exchange.Connection); } @@ -139,6 +146,12 @@ public async ValueTask OpenConnectionToRemote( : RemoteConnectionResultType.Http11; exchange.Connection.ReadStream = exchange.Connection.WriteStream = resultStream; + exchange.Connection.HttpVersion = protoType == RemoteConnectionResultType.Http2 ? "HTTP/2" : "HTTP/1.1"; + + FluxzyLogEvents.LogConnectionOpened( + setting.GetLogger(), + exchange.Connection, + proxyConfiguration != null); return new RemoteConnectionResult(protoType, exchange.Connection); } diff --git a/src/Fluxzy.Core/Clients/PoolBuilder.cs b/src/Fluxzy.Core/Clients/PoolBuilder.cs index 94dd450ae..b09ab45de 100644 --- a/src/Fluxzy.Core/Clients/PoolBuilder.cs +++ b/src/Fluxzy.Core/Clients/PoolBuilder.cs @@ -11,10 +11,13 @@ using Fluxzy.Clients.H2; using Fluxzy.Clients.Mock; using Fluxzy.Core; +using Fluxzy.Logging; using Fluxzy.Misc; using Fluxzy.Rules; using Fluxzy.Utils; using Fluxzy.Writers; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Fluxzy.Clients { @@ -42,6 +45,7 @@ static PoolBuilder() private readonly RemoteConnectionBuilder _remoteConnectionBuilder; private readonly ITimingProvider _timingProvider; + private readonly ILogger _logger; private readonly ConcurrentDictionary _dnsSolversCache = new(); @@ -51,12 +55,14 @@ public PoolBuilder( RemoteConnectionBuilder remoteConnectionBuilder, ITimingProvider timingProvider, RealtimeArchiveWriter archiveWriter, - IDnsSolver dnsSolver) + IDnsSolver dnsSolver, + ILoggerFactory? loggerFactory = null) { _remoteConnectionBuilder = remoteConnectionBuilder; _timingProvider = timingProvider; _archiveWriter = archiveWriter; _dnsSolver = dnsSolver; + _logger = (loggerFactory ?? NullLoggerFactory.Instance).CreateLogger(); } /// @@ -71,11 +77,24 @@ public async ValueTask Exchange exchange, ProxyRuntimeSetting proxyRuntimeSetting, CancellationToken cancellationToken = default) + { + var pool = await GetPoolCore(exchange, proxyRuntimeSetting, _logger, cancellationToken) + .ConfigureAwait(false); + FluxzyLogEvents.LogConnectionPoolResolved(_logger, exchange, pool); + return pool; + } + + private async ValueTask + GetPoolCore( + Exchange exchange, + ProxyRuntimeSetting proxyRuntimeSetting, + ILogger logger, + CancellationToken cancellationToken) { var dnsSolver = ResolveDnsProvider(exchange, proxyRuntimeSetting); - var computeDnsPromise = - DnsUtility.ComputeDnsUpdateExchange(exchange, _timingProvider, dnsSolver, proxyRuntimeSetting); + var computeDnsPromise = + DnsUtility.ComputeDnsUpdateExchange(exchange, _timingProvider, dnsSolver, proxyRuntimeSetting, logger); var dnsResolutionResult = await computeDnsPromise.ConfigureAwait(false); @@ -222,7 +241,8 @@ await proxyRuntimeSetting.EnforceRules(exchange.Context, openingResult.Connection .ReadStream!, // Read and write stream are the same after the sslhandshake exchange.Context.AdvancedTlsSettings.H2StreamSetting ?? new H2StreamSetting(), - exchange.Authority, exchange.Connection!, OnConnectionFaulted); + exchange.Authority, exchange.Connection!, OnConnectionFaulted, + proxyRuntimeSetting.GetLogger()); exchange.HttpVersion = exchange.Connection!.HttpVersion = "HTTP/2"; @@ -260,6 +280,8 @@ private void OnConnectionFaulted(IHttpConnectionPool h2ConnectionPool) if (!removed) return; + FluxzyLogEvents.LogConnectionEvicted(_logger, h2ConnectionPool, "PoolFaulted"); + // Disposal runs asynchronously after the H2ConnectionPool's own // OnLoopEnd cleanup has completed (see the reordering in // H2ConnectionPool.OnLoopEnd). We do not block the caller here, but we diff --git a/src/Fluxzy.Core/Core/Exchange.cs b/src/Fluxzy.Core/Core/Exchange.cs index 5028ae02a..08b42cff3 100644 --- a/src/Fluxzy.Core/Core/Exchange.cs +++ b/src/Fluxzy.Core/Core/Exchange.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; using System.Collections.Specialized; +using System.Diagnostics; using System.IO; using System.Linq; using System.Threading.Tasks; @@ -153,6 +154,8 @@ public Exchange( internal TaskCompletionSource ExchangeCompletionSource { get; } = new(TaskCreationOptions.RunContinuationsAsynchronously); + internal Activity? LogActivity { get; set; } + public ExchangeContext Context { get; } public bool RunInLiveEdit { get; set; } diff --git a/src/Fluxzy.Core/Core/H2DownStreamPipe.cs b/src/Fluxzy.Core/Core/H2DownStreamPipe.cs index 53395e16b..e890a513c 100644 --- a/src/Fluxzy.Core/Core/H2DownStreamPipe.cs +++ b/src/Fluxzy.Core/Core/H2DownStreamPipe.cs @@ -52,7 +52,6 @@ internal class H2DownStreamPipe : IDownStreamPipe private int _writeSignalState; private int _writeLoopIterations; - private readonly H2Logger _logger; private readonly CancellationToken _mainLoopToken; private readonly CancellationTokenSource _mainLoopTokenSource; @@ -85,7 +84,6 @@ public H2DownStreamPipe( ArrayPoolMemoryProvider.Default)); _headerEncoder = new HeaderEncoder(hPackEncoder, hPackDecoder, _h2StreamSetting); - _logger = new H2Logger(requestedAuthority, -1); _ringBuffer = new CircularWriteBuffer(RingBufferCapacity, SignalWriteLoop); _dataChannel = Channel.CreateUnbounded( new UnboundedChannelOptions() { SingleReader = true }); @@ -314,7 +312,7 @@ private async Task ReadLoop(CancellationToken token) if (!_currentStreams.TryGetValue(frame.StreamIdentifier, out var worker)) { worker = new ServerStreamWorker(frame.StreamIdentifier, _headerEncoder, - _h2StreamSetting, _logger); + _h2StreamSetting); _currentStreams.TryAdd(frame.StreamIdentifier, worker); diff --git a/src/Fluxzy.Core/Core/Impl/SecureConnectionUpdater.cs b/src/Fluxzy.Core/Core/Impl/SecureConnectionUpdater.cs index b4d6e489f..882cb3756 100644 --- a/src/Fluxzy.Core/Core/Impl/SecureConnectionUpdater.cs +++ b/src/Fluxzy.Core/Core/Impl/SecureConnectionUpdater.cs @@ -10,8 +10,10 @@ using System.Security.Cryptography.X509Certificates; using System.Threading; using System.Threading.Tasks; +using Fluxzy.Logging; using Fluxzy.Misc.Streams; -using Fluxzy.Misc.Traces; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Fluxzy.Core { @@ -23,11 +25,14 @@ internal class SecureConnectionUpdater private readonly ICertificateProvider _certificateProvider; private readonly bool _serveH2; + private readonly ILogger _logger; - public SecureConnectionUpdater(ICertificateProvider certificateProvider, bool serveH2) + public SecureConnectionUpdater( + ICertificateProvider certificateProvider, bool serveH2, ILogger? logger = null) { _certificateProvider = certificateProvider; _serveH2 = serveH2; + _logger = logger ?? NullLogger.Instance; } [MethodImpl(MethodImplOptions.AggressiveInlining)] @@ -64,10 +69,7 @@ public async Task AuthenticateAsServer( certificate = context.ServerCertificate ?? _certificateProvider.GetCertificate(host); } catch (Exception e) { - if (D.EnableTracing) { - D.TraceException(e, "An error occured while getting certificate"); - } - + FluxzyLogEvents.CertificateResolutionFailed(_logger, e, host); throw; } diff --git a/src/Fluxzy.Core/Core/ProxyOrchestrator.cs b/src/Fluxzy.Core/Core/ProxyOrchestrator.cs index 41faa245d..3f84670b7 100644 --- a/src/Fluxzy.Core/Core/ProxyOrchestrator.cs +++ b/src/Fluxzy.Core/Core/ProxyOrchestrator.cs @@ -10,12 +10,13 @@ using Fluxzy.Clients; using Fluxzy.Clients.Mock; using Fluxzy.Extensions; +using Fluxzy.Logging; using Fluxzy.Misc.ResizableBuffers; using Fluxzy.Misc.Streams; -using Fluxzy.Misc.Traces; using Fluxzy.Rules; using Fluxzy.Utils.ProcessTracking; using Fluxzy.Writers; +using Microsoft.Extensions.Logging; using Org.BouncyCastle.Tls; namespace Fluxzy.Core @@ -26,6 +27,7 @@ internal class ProxyOrchestrator : IDisposable private readonly ExchangeSourceProvider _exchangeSourceProvider; private readonly PoolBuilder _poolBuilder; private readonly ProxyRuntimeSetting _proxyRuntimeSetting; + private readonly ILogger _logger; public ProxyOrchestrator( ProxyRuntimeSetting proxyRuntimeSetting, @@ -36,12 +38,23 @@ public ProxyOrchestrator( _exchangeSourceProvider = exchangeSourceProvider; _poolBuilder = poolBuilder; _archiveWriter = proxyRuntimeSetting.ArchiveWriter; + _logger = proxyRuntimeSetting.GetLogger(); } public void Dispose() { } + private static string SafeRemoteEndPoint(TcpClient client) + { + try { + return client.Client.RemoteEndPoint?.ToString() ?? string.Empty; + } + catch { + return string.Empty; + } + } + public async ValueTask Operate( TcpClient client, RsBuffer buffer, bool closeImmediately, CancellationToken token) { @@ -51,12 +64,6 @@ public async ValueTask Operate( try { - if (D.EnableTracing) - { - var message = $"Receive from {client.Client.RemoteEndPoint}"; - D.TraceInfo(message); - } - using var callerTokenSource = CancellationTokenSource.CreateLinkedTokenSource(token); token = callerTokenSource.Token; @@ -77,18 +84,13 @@ public async ValueTask Operate( { // Failure from the local connection - if (D.EnableTracing) - { - var message = $"Client connection failure {client.Client.RemoteEndPoint}"; - D.TraceException(ex, message); - } + var remote = SafeRemoteEndPoint(client); + FluxzyLogEvents.ClientConnectionInitFailed(_logger, ex, remote); var errorInfo = DownstreamErrorInfo.CreateFrom(client, ex); _archiveWriter.Update(errorInfo, token); - // Logs into the secure logger - if (ex is SocketException || ex is IOException) { return; @@ -129,12 +131,6 @@ await OperateSequential( { if (ex is OperationCanceledException) { - if (D.EnableTracing) - { - var message = $"Error from {client.Client.RemoteEndPoint}"; - D.TraceException(ex, message); - } - return; } @@ -184,14 +180,9 @@ private async ValueTask OperateSequential( lastExchangeHolder.Exchange = exchange; } - catch (IOException ex) + catch (IOException) { - if (D.EnableTracing) - { - var message = $"Error from {client.Client.RemoteEndPoint}"; - D.TraceException(ex, message); - } - + // Client closed mid-read — normal connection-close path. return; } @@ -343,6 +334,8 @@ private async ValueTask EnterProcessExchange( UpdateExchangeMetrics(exchange, remoteEndPoint, downStreamClientAddress, localEndPoint, localEndPointsAddress); + using var exchangeLogScope = FluxzyLoggerScopes.BeginExchangeScope(_logger, exchange); + if (!exchange.Unprocessed && _proxyRuntimeSetting.UserAgentProvider != null) { var userAgentValue = exchange.GetRequestHeaderValue("User-Agent"); @@ -359,6 +352,13 @@ private async ValueTask EnterProcessExchange( exchange.ProcessInfo = ProcessTracker.Instance.GetProcessInfo(remoteEndPoint.Port); } + if (!exchange.Unprocessed) + { + exchange.LogActivity = FluxzyActivitySource.StartExchangeActivity( + exchange, _proxyRuntimeSetting.ProxyInstanceId); + FluxzyLogEvents.LogRequestResolutionStarted(_logger, exchange); + } + var shouldCloseDownStreamConnection = await InternalProcessExchange(exchange, downStreamPipe, buffer, closeImmediately, callerTokenSource, token); @@ -394,13 +394,7 @@ private async Task InternalProcessExchange( if (processMessage) { - // Check whether the local browser ask for a connection close - - if (D.EnableTracing) - { - var message = $"[#{exchange.Id}] Processing {exchange.Request.Header.Authority}"; - D.TraceInfo(message); - } + // Check whether the local browser ask for a connection close shouldCloseConnectionToDownStream = closeImmediately || exchange.ShouldClose(); @@ -488,19 +482,13 @@ await exchange.Context.BreakPointContext.RequestHeaderCompletion } else { - // get a connection pool for the current exchange + // get a connection pool for the current exchange connectionPool = await _poolBuilder .GetPool(exchange, _proxyRuntimeSetting, token) .ConfigureAwait(false); } - if (D.EnableTracing) - { - var message = $"[#{exchange.Id}] Pool received"; - D.TraceInfo(message); - } - - // Actual request send + // Actual request send try { @@ -512,12 +500,6 @@ await connectionPool.Send(exchange, { shouldCloseConnectionToDownStream = true; } - - if (D.EnableTracing) - { - var message = $"[#{exchange.Id}] Response received"; - D.TraceInfo(message); - } } catch (Exception ex) { @@ -668,12 +650,6 @@ await exchange.Context.BreakPointContext.ResponseHeaderCompletion CancellationToken.None ); - if (D.EnableTracing) - { - var message = $"[#{ext.Id}] Response body done"; - D.TraceInfo(message); - } - return default; }; @@ -786,6 +762,8 @@ await SafeCloseResponseBody(exchange, originalResponseBodyStream) { // Enhance your calm } + + FluxzyLogEvents.LogExchangeCompleted(_logger, exchange, _proxyRuntimeSetting.StartupSetting); } else { diff --git a/src/Fluxzy.Core/Core/ProxyRuntimeSetting.cs b/src/Fluxzy.Core/Core/ProxyRuntimeSetting.cs index 128d4ad60..267ad6f0f 100644 --- a/src/Fluxzy.Core/Core/ProxyRuntimeSetting.cs +++ b/src/Fluxzy.Core/Core/ProxyRuntimeSetting.cs @@ -12,6 +12,8 @@ using Fluxzy.Rules.Actions; using Fluxzy.Rules.Filters; using Fluxzy.Writers; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Fluxzy.Core { @@ -27,6 +29,7 @@ private ProxyRuntimeSetting() ExecutionContext = null!; CertificateValidationCallback = null!; ActionMapping = new SetUserAgentActionMapping(null); + LoggerFactory = NullLoggerFactory.Instance; } public ProxyRuntimeSetting( @@ -35,7 +38,9 @@ public ProxyRuntimeSetting( ITcpConnectionProvider tcpConnectionProvider, RealtimeArchiveWriter archiveWriter, IIdProvider idProvider, - IUserAgentInfoProvider? userAgentProvider) + IUserAgentInfoProvider? userAgentProvider, + ILoggerFactory? loggerFactory = null, + Guid proxyInstanceId = default) { ExecutionContext = null!; CertificateValidationCallback = null!; @@ -48,6 +53,8 @@ public ProxyRuntimeSetting( ConcurrentConnection = startupSetting.ConnectionPerHost; ExpectContinueTimeout = startupSetting.ExpectContinueTimeout; ActionMapping = new SetUserAgentActionMapping(startupSetting.UserAgentActionConfigurationFile); + LoggerFactory = loggerFactory ?? NullLoggerFactory.Instance; + ProxyInstanceId = proxyInstanceId; } internal static ProxyRuntimeSetting CreateDefault => new() { @@ -86,12 +93,18 @@ public ProxyRuntimeSetting( public IUserAgentInfoProvider? UserAgentProvider { get; } + public ILoggerFactory LoggerFactory { get; } + + public ILogger GetLogger() => LoggerFactory.CreateLogger(); + public VariableContext VariableContext { get; } = new(); public HashSet EndPoints { get; set; } = new(); public int ProxyListenPort { get; set; } + public Guid ProxyInstanceId { get; } + public ProxyConfiguration? GetInternalProxyAuthentication() { var preferredEndPoint = EndPoints diff --git a/src/Fluxzy.Core/Core/ServerStreamWorker.cs b/src/Fluxzy.Core/Core/ServerStreamWorker.cs index 0b1cf9f6b..a51409d96 100644 --- a/src/Fluxzy.Core/Core/ServerStreamWorker.cs +++ b/src/Fluxzy.Core/Core/ServerStreamWorker.cs @@ -52,14 +52,13 @@ internal class ServerStreamWorker : IDisposable public ServerStreamWorker( int streamIdentifier, IHeaderEncoder headerEncoder, - H2StreamSetting h2StreamSetting, - H2Logger logger) + H2StreamSetting h2StreamSetting) { StreamIdentifier = streamIdentifier; _headerEncoder = headerEncoder; _h2StreamSetting = h2StreamSetting; _headerBuffer = ArrayPool.Shared.Rent(h2StreamSetting.MaxHeaderSize); - _streamWindowSizeHolder = new WindowSizeHolder(logger, h2StreamSetting.Remote.WindowSize, streamIdentifier); + _streamWindowSizeHolder = new WindowSizeHolder(h2StreamSetting.Remote.WindowSize, streamIdentifier); } private H2ErrorCode ReceiveHeaderFragment(ReadOnlySpan data, bool endHeaders) diff --git a/src/Fluxzy.Core/Fluxzy.Core.csproj b/src/Fluxzy.Core/Fluxzy.Core.csproj index 22d8d64cb..13e1e40f0 100644 --- a/src/Fluxzy.Core/Fluxzy.Core.csproj +++ b/src/Fluxzy.Core/Fluxzy.Core.csproj @@ -45,6 +45,7 @@ + diff --git a/src/Fluxzy.Core/FluxzySetting.cs b/src/Fluxzy.Core/FluxzySetting.cs index 94648a057..4e1fde4f2 100644 --- a/src/Fluxzy.Core/FluxzySetting.cs +++ b/src/Fluxzy.Core/FluxzySetting.cs @@ -259,6 +259,28 @@ public FluxzySetting() [JsonInclude] public List ProtoDirectories { get; internal set; } = new(); + /// + /// When false (default), header values whose name matches + /// are replaced with "<redacted, len=N>" in Trace-level envelope logs (event 1099). + /// Set to true only when you accept emitting credentials and cookies to your logging backend. + /// + [JsonInclude] + public bool LogIncludeSensitiveHeaders { get; internal set; } + + /// + /// Case-insensitive set of header names whose values are redacted in Trace-level + /// envelope logs unless is true. + /// + [JsonInclude] + public HashSet LogRedactedHeaders { get; internal set; } = + new(StringComparer.OrdinalIgnoreCase) { + "Authorization", + "Proxy-Authorization", + "Cookie", + "Set-Cookie", + "X-Auth-Token" + }; + internal IEnumerable FixedRules() { if (GlobalSkipSslDecryption) { diff --git a/src/Fluxzy.Core/Logging/FluxzyActivitySource.cs b/src/Fluxzy.Core/Logging/FluxzyActivitySource.cs new file mode 100644 index 000000000..9e25ab52a --- /dev/null +++ b/src/Fluxzy.Core/Logging/FluxzyActivitySource.cs @@ -0,0 +1,128 @@ +// Copyright 2021 - Haga Rakotoharivelo - https://github.com/haga-rak + +using System; +using System.Diagnostics; +using Fluxzy.Clients; +using Fluxzy.Clients.H11; +using Fluxzy.Clients.H2; +using Fluxzy.Clients.Mock; +using Fluxzy.Core; +using Fluxzy.Extensions; + +namespace Fluxzy.Logging +{ + internal static class FluxzyActivitySource + { + public const string SourceName = "Fluxzy.Core"; + + public static readonly ActivitySource Instance = new( + SourceName, + typeof(FluxzyActivitySource).Assembly.GetName().Version?.ToString() ?? "0.0.0"); + + public static Activity? StartExchangeActivity(Exchange exchange, Guid proxyInstanceId) + { + var traceparent = exchange.GetRequestHeaderValue("traceparent"); + var tracestate = exchange.GetRequestHeaderValue("tracestate"); + + Activity? activity; + if (!string.IsNullOrEmpty(traceparent) + && ActivityContext.TryParse(traceparent, tracestate, out var parentContext)) { + activity = Instance.StartActivity( + "HTTP " + exchange.Method, ActivityKind.Server, parentContext); + } + else { + activity = Instance.StartActivity( + "HTTP " + exchange.Method, ActivityKind.Server); + } + + if (activity == null) + return null; + + activity.SetTag("http.request.method", exchange.Method); + activity.SetTag("url.full", exchange.FullUrl); + activity.SetTag("server.address", exchange.Authority.HostName); + activity.SetTag("server.port", exchange.Authority.Port); + activity.SetTag("fluxzy.exchange_id", exchange.Id); + activity.SetTag("fluxzy.proxy.instance_id", proxyInstanceId); + + var ua = exchange.GetRequestHeaderValue("User-Agent"); + if (ua != null) + activity.SetTag("user_agent.original", ua); + + var clientIp = exchange.Metrics.DownStreamClientAddress; + if (!string.IsNullOrEmpty(clientIp)) { + activity.SetTag("client.address", clientIp); + activity.SetTag("client.port", exchange.Metrics.DownStreamClientPort); + } + + return activity; + } + + public static void TagDnsResolved(Activity? activity, double dnsMs, bool wasForced) + { + if (activity == null) + return; + + activity.SetTag("fluxzy.dns.duration_ms", dnsMs); + activity.SetTag("fluxzy.dns.forced", wasForced); + } + + public static void TagPoolResolved(Activity? activity, IHttpConnectionPool pool, bool reused) + { + if (activity == null) + return; + + activity.SetTag("fluxzy.pool.type", PoolTypeName(pool)); + activity.SetTag("fluxzy.pool.reused", reused); + } + + public static void TagResponseHeader(Activity? activity, int statusCode) + { + if (activity == null || statusCode == 0) + return; + + activity.SetTag("http.response.status_code", statusCode); + } + + public static void EnrichOnComplete(Activity? activity, Exchange exchange) + { + if (activity == null) + return; + + if (!string.IsNullOrEmpty(exchange.HttpVersion)) + activity.SetTag("network.protocol.version", exchange.HttpVersion); + + var status = exchange.Response.Header?.StatusCode ?? 0; + + if (status > 0) + activity.SetTag("http.response.status_code", status); + + var requestBodyBytes = exchange.Metrics.TotalSent - exchange.Metrics.RequestHeaderLength; + if (requestBodyBytes > 0) + activity.SetTag("http.request.body.size", requestBodyBytes); + + var responseBodyBytes = exchange.Metrics.TotalReceived - exchange.Metrics.ResponseHeaderLength; + if (responseBodyBytes > 0) + activity.SetTag("http.response.body.size", responseBodyBytes); + + if (exchange.Errors.Count > 0 || exchange.Context.Abort) + activity.SetStatus(ActivityStatusCode.Error); + else if (status >= 500) + activity.SetStatus(ActivityStatusCode.Error); + else if (status >= 200 && status < 400) + activity.SetStatus(ActivityStatusCode.Ok); + } + + private static string PoolTypeName(IHttpConnectionPool pool) + { + return pool switch { + Http11ConnectionPool => "Http11", + H2ConnectionPool => "H2", + MockedConnectionPool => "Mocked", + TunnelOnlyConnectionPool => "Tunnel", + WebsocketConnectionPool => "Websocket", + _ => pool.GetType().Name + }; + } + } +} diff --git a/src/Fluxzy.Core/Logging/FluxzyLogEvents.cs b/src/Fluxzy.Core/Logging/FluxzyLogEvents.cs new file mode 100644 index 000000000..047bb7770 --- /dev/null +++ b/src/Fluxzy.Core/Logging/FluxzyLogEvents.cs @@ -0,0 +1,457 @@ +// Copyright 2021 - Haga Rakotoharivelo - https://github.com/haga-rak + +using System; +using System.Net; +using Fluxzy.Clients; +using Fluxzy.Clients.H11; +using Fluxzy.Clients.H2; +using Fluxzy.Clients.Mock; +using Fluxzy.Core; +using Fluxzy.Extensions; +using Microsoft.Extensions.Logging; + +namespace Fluxzy.Logging +{ +#pragma warning disable SYSLIB1015 // Argument not referenced from message template — emitted as structured property only + internal static partial class FluxzyLogEvents + { + [LoggerMessage(EventId = 1001, Level = LogLevel.Debug, + Message = "Client connection accepted (concurrent={ConcurrentCount}, closeImmediately={CloseImmediately})")] + public static partial void ClientConnectionAccepted( + ILogger logger, + int ConcurrentCount, + bool CloseImmediately); + + [LoggerMessage(EventId = 1002, Level = LogLevel.Debug, + Message = "Resolving request {Method} {FullUrl}")] + public static partial void RequestResolutionStarted( + ILogger logger, + string Method, + string FullUrl, + bool IsSecure, + bool IsWebSocket, + bool HasRequestBody, + long RequestContentLength, + string? UserAgent, + int? ProcessId, + string? ProcessPath); + + [LoggerMessage(EventId = 1003, Level = LogLevel.Debug, + Message = "DNS {HostName} -> {RemoteIp} in {DnsMs}ms via {DnsResolver}")] + public static partial void DnsResolved( + ILogger logger, + string HostName, + string RemoteIp, + int RemotePort, + double DnsMs, + string DnsResolver, + bool WasForced, + string? UpstreamProxyHost, + int? UpstreamProxyPort); + + [LoggerMessage(EventId = 1004, Level = LogLevel.Debug, + Message = "Pool {PoolType} (reused={ReusingConnection}, getPoolMs={GetPoolMs}ms)")] + public static partial void ConnectionPoolResolved( + ILogger logger, + string PoolType, + bool ReusingConnection, + double GetPoolMs, + int? ConnectionId, + string? RemoteIp, + int? RemotePort, + string? LocalIp, + int? LocalPort, + string? Alpn, + string? TlsProtocol, + string? CipherSuite, + string? SniSent, + double? TlsHandshakeMs, + double? TcpConnectMs, + bool IsBlindTunnel, + bool IsMocked); + + [LoggerMessage(EventId = 1005, Level = LogLevel.Debug, + Message = "Sending request on connection {ConnectionId}")] + public static partial void RequestSending( + ILogger logger, + int ConnectionId, + int RequestHeaderLength, + bool HasExpectContinue, + bool HasRequestBody, + long RequestContentLength, + bool Chunked, + int RequestProcessedOnConnection); + + [LoggerMessage(EventId = 1006, Level = LogLevel.Debug, + Message = "Request sent in {SendMs}ms ({BytesSent} bytes)")] + public static partial void RequestSent( + ILogger logger, + int ConnectionId, + long BytesSent, + long RequestBodyBytes, + double SendMs, + double HeaderSendMs, + double BodySendMs, + bool EarlyResponse); + + [LoggerMessage(EventId = 1007, Level = LogLevel.Debug, + Message = "Response {StatusCode} ({TtfbMs}ms TTFB)")] + public static partial void ResponseHeaderReceived( + ILogger logger, + int ConnectionId, + int StatusCode, + string? ReasonPhrase, + int ResponseHeaderLength, + long ResponseContentLength, + bool ResponseChunked, + bool ConnectionCloseRequest, + double TtfbMs, + double ResponseHeaderReadMs, + bool HasResponseBody, + string? ContentEncoding, + string? ContentType, + string? Server); + + [LoggerMessage(EventId = 1008, Level = LogLevel.Debug, + Message = "Exchange done {StatusCode} totalMs={TotalMs} sent={TotalSent} recv={TotalReceived}")] + public static partial void ExchangeCompleted( + ILogger logger, + int ConnectionId, + int StatusCode, + string FullUrl, + double TotalMs, + double DnsMs, + double GetPoolMs, + double TcpConnectMs, + double TlsHandshakeMs, + double SendMs, + double TtfbMs, + double ResponseBodyMs, + long TotalSent, + long TotalReceived, + int RequestHeaderLength, + int ResponseHeaderLength, + bool ReusingConnection, + int RequestProcessedOnConnection, + int ErrorCount, + bool Aborted, + bool ClosedRemote); + + [LoggerMessage(EventId = 1009, Level = LogLevel.Debug, + Message = "Pool evicted {Authority} (reason={Reason})")] + public static partial void ConnectionEvicted( + ILogger logger, + string Authority, + string Reason, + int? ConnectionId); + + [LoggerMessage(EventId = 1010, Level = LogLevel.Debug, + Message = "Connection opened to {RemoteIp}:{RemotePort} ({HttpVersion}, tls={TlsProtocol}, handshakeMs={TlsHandshakeMs})")] + public static partial void ConnectionOpened( + ILogger logger, + int ConnectionId, + string Authority, + string RemoteIp, + int RemotePort, + int LocalPort, + string HttpVersion, + string? Alpn, + string? TlsProtocol, + string? CipherSuite, + string? SniSent, + double TcpConnectMs, + double TlsHandshakeMs, + double ProxyConnectMs, + bool ViaUpstreamProxy); + + [LoggerMessage(EventId = 1099, Level = LogLevel.Trace, + Message = "Exchange envelope {ExchangeId}")] + public static partial void ExchangeEnvelope( + ILogger logger, + int ExchangeId, + string RequestHeaders, + string? ResponseHeaders, + string? Trailers); + + [LoggerMessage(EventId = 2001, Level = LogLevel.Warning, + Message = "Client connection init failed from {RemoteEndPoint}")] + public static partial void ClientConnectionInitFailed( + ILogger logger, + Exception exception, + string RemoteEndPoint); + + [LoggerMessage(EventId = 2002, Level = LogLevel.Warning, + Message = "Certificate resolution failed for {Host}")] + public static partial void CertificateResolutionFailed( + ILogger logger, + Exception exception, + string Host); + + [LoggerMessage(EventId = 3001, Level = LogLevel.Error, + Message = "Unhandled connection processing error from {RemoteEndPoint}")] + public static partial void ConnectionProcessingError( + ILogger logger, + Exception exception, + string RemoteEndPoint); + + public static void LogRequestResolutionStarted(ILogger logger, Exchange exchange) + { + if (!logger.IsEnabled(LogLevel.Debug)) + return; + + var body = exchange.Request.Body; + var hasReqBody = body != null && (!body.CanSeek || body.Length > 0); + + RequestResolutionStarted(logger, + Method: exchange.Method, + FullUrl: exchange.FullUrl, + IsSecure: exchange.Authority.Secure, + IsWebSocket: exchange.IsWebSocket, + HasRequestBody: hasReqBody, + RequestContentLength: exchange.Request.Header.ContentLength, + UserAgent: exchange.GetRequestHeaderValue("User-Agent"), + ProcessId: exchange.ProcessInfo?.ProcessId, + ProcessPath: exchange.ProcessInfo?.ProcessPath); + } + + public static void LogDnsResolved( + ILogger logger, + Exchange exchange, + string hostName, + IPAddress remoteIp, + int remotePort, + DateTime dnsSolveStart, + DateTime dnsSolveEnd, + IDnsSolver dnsSolver, + bool wasForced) + { + var dnsMs = wasForced ? 0 : Ms(dnsSolveStart, dnsSolveEnd); + + FluxzyActivitySource.TagDnsResolved(exchange.LogActivity, dnsMs, wasForced); + + if (!logger.IsEnabled(LogLevel.Debug)) + return; + + var proxy = exchange.Context.ProxyConfiguration; + + DnsResolved(logger, + HostName: hostName, + RemoteIp: remoteIp.ToString(), + RemotePort: remotePort, + DnsMs: dnsMs, + DnsResolver: dnsSolver.GetType().Name, + WasForced: wasForced, + UpstreamProxyHost: proxy?.Host, + UpstreamProxyPort: proxy?.Port); + } + + public static void LogConnectionPoolResolved(ILogger logger, Exchange exchange, IHttpConnectionPool pool) + { + FluxzyActivitySource.TagPoolResolved(exchange.LogActivity, pool, exchange.Metrics.ReusingConnection); + + if (!logger.IsEnabled(LogLevel.Debug)) + return; + + var c = exchange.Connection; + var ssl = c?.SslInfo; + + var poolType = pool switch { + Http11ConnectionPool => "Http11", + H2ConnectionPool => "H2", + MockedConnectionPool => "Mocked", + TunnelOnlyConnectionPool => "Tunnel", + WebsocketConnectionPool => "Websocket", + _ => pool.GetType().Name + }; + + ConnectionPoolResolved(logger, + PoolType: poolType, + ReusingConnection: exchange.Metrics.ReusingConnection, + GetPoolMs: Ms(exchange.Metrics.ReceivedFromProxy, exchange.Metrics.RetrievingPool), + ConnectionId: c?.Id, + RemoteIp: c?.RemoteAddress?.ToString(), + RemotePort: c == null ? null : exchange.Authority.Port, + LocalIp: c?.LocalAddress, + LocalPort: c?.LocalPort, + Alpn: ssl?.NegotiatedApplicationProtocol, + TlsProtocol: ssl?.SslProtocol.ToString(), + CipherSuite: ssl?.NegotiatedCipherSuite.ToString(), + SniSent: c == null || !exchange.Authority.Secure ? null : exchange.Authority.HostName, + TlsHandshakeMs: c == null ? null : Ms(c.SslNegotiationStart, c.SslNegotiationEnd), + TcpConnectMs: c == null ? null : Ms(c.TcpConnectionOpening, c.TcpConnectionOpened), + IsBlindTunnel: pool is TunnelOnlyConnectionPool, + IsMocked: pool is MockedConnectionPool); + } + + public static void LogRequestSending(ILogger logger, Exchange exchange) + { + if (!logger.IsEnabled(LogLevel.Debug)) + return; + + var c = exchange.Connection; + var body = exchange.Request.Body; + var hasReqBody = body != null && (!body.CanSeek || body.Length > 0); + + RequestSending(logger, + ConnectionId: c?.Id ?? 0, + RequestHeaderLength: exchange.Metrics.RequestHeaderLength, + HasExpectContinue: exchange.Request.Header.HasExpectContinue, + HasRequestBody: hasReqBody, + RequestContentLength: exchange.Request.Header.ContentLength, + Chunked: exchange.Request.Header.ChunkedBody, + RequestProcessedOnConnection: c?.RequestProcessed ?? 0); + } + + public static void LogRequestSent(ILogger logger, Exchange exchange, bool earlyResponse) + { + if (!logger.IsEnabled(LogLevel.Debug)) + return; + + var m = exchange.Metrics; + var bytesSent = m.TotalSent; + var bodyBytes = bytesSent - m.RequestHeaderLength; + + RequestSent(logger, + ConnectionId: exchange.Connection?.Id ?? 0, + BytesSent: bytesSent, + RequestBodyBytes: bodyBytes < 0 ? 0 : bodyBytes, + SendMs: Ms(m.RequestHeaderSending, m.RequestBodySent), + HeaderSendMs: Ms(m.RequestHeaderSending, m.RequestHeaderSent), + BodySendMs: Ms(m.RequestHeaderSent, m.RequestBodySent), + EarlyResponse: earlyResponse); + } + + public static void LogResponseHeaderReceived(ILogger logger, Exchange exchange) + { + FluxzyActivitySource.TagResponseHeader( + exchange.LogActivity, exchange.Response.Header?.StatusCode ?? 0); + + if (!logger.IsEnabled(LogLevel.Debug)) + return; + + var m = exchange.Metrics; + var header = exchange.Response.Header; + + ResponseHeaderReceived(logger, + ConnectionId: exchange.Connection?.Id ?? 0, + StatusCode: header?.StatusCode ?? 0, + ReasonPhrase: null, + ResponseHeaderLength: m.ResponseHeaderLength, + ResponseContentLength: header?.ContentLength ?? -1, + ResponseChunked: header?.ChunkedBody ?? false, + ConnectionCloseRequest: header?.ConnectionCloseRequest ?? false, + TtfbMs: Ms(m.RequestHeaderSending, m.ResponseHeaderEnd), + ResponseHeaderReadMs: Ms(m.ResponseHeaderStart, m.ResponseHeaderEnd), + HasResponseBody: header != null + && header.HasResponseBody(exchange.Request.Header.Method.Span, out _), + ContentEncoding: exchange.GetResponseHeaderValue("Content-Encoding"), + ContentType: exchange.GetResponseHeaderValue("Content-Type"), + Server: exchange.GetResponseHeaderValue("Server")); + } + + public static void LogExchangeCompleted(ILogger logger, Exchange exchange, FluxzySetting? setting = null) + { + var activity = exchange.LogActivity; + if (activity != null) { + FluxzyActivitySource.EnrichOnComplete(activity, exchange); + activity.Dispose(); + exchange.LogActivity = null; + } + + if (logger.IsEnabled(LogLevel.Trace)) { + LogExchangeEnvelope(logger, exchange, setting); + } + + if (!logger.IsEnabled(LogLevel.Debug)) + return; + + var m = exchange.Metrics; + var c = exchange.Connection; + + ExchangeCompleted(logger, + ConnectionId: c?.Id ?? 0, + StatusCode: exchange.Response.Header?.StatusCode ?? 0, + FullUrl: exchange.FullUrl, + TotalMs: Ms(m.ReceivedFromProxy, m.ResponseBodyEnd), + DnsMs: c == null ? 0 : Ms(c.DnsSolveStart, c.DnsSolveEnd), + GetPoolMs: Ms(m.ReceivedFromProxy, m.RetrievingPool), + TcpConnectMs: c == null ? 0 : Ms(c.TcpConnectionOpening, c.TcpConnectionOpened), + TlsHandshakeMs: c == null ? 0 : Ms(c.SslNegotiationStart, c.SslNegotiationEnd), + SendMs: Ms(m.RequestHeaderSending, m.RequestBodySent), + TtfbMs: Ms(m.RequestHeaderSending, m.ResponseHeaderEnd), + ResponseBodyMs: Ms(m.ResponseBodyStart, m.ResponseBodyEnd), + TotalSent: m.TotalSent, + TotalReceived: m.TotalReceived, + RequestHeaderLength: m.RequestHeaderLength, + ResponseHeaderLength: m.ResponseHeaderLength, + ReusingConnection: m.ReusingConnection, + RequestProcessedOnConnection: c?.RequestProcessed ?? 0, + ErrorCount: exchange.Errors.Count, + Aborted: exchange.Context.Abort, + ClosedRemote: m.RemoteClosed != default); + } + + public static void LogExchangeEnvelope(ILogger logger, Exchange exchange, FluxzySetting? setting) + { + var requestHeaders = HeaderRedactor.FormatHeaders(exchange.GetRequestHeaders(), setting); + var responseHeaders = HeaderRedactor.FormatHeaders(exchange.GetResponseHeaders(), setting); + + var trailers = exchange.GetResponseTrailers(); + var trailerString = trailers == null + ? null + : HeaderRedactor.FormatHeaders(trailers, setting); + + ExchangeEnvelope(logger, + ExchangeId: exchange.Id, + RequestHeaders: requestHeaders, + ResponseHeaders: responseHeaders, + Trailers: trailerString); + } + + public static void LogConnectionEvicted(ILogger logger, IHttpConnectionPool pool, string reason) + { + if (!logger.IsEnabled(LogLevel.Debug)) + return; + + int? connectionId = pool switch { + H2ConnectionPool h2 => h2.Id, + _ => null + }; + + ConnectionEvicted(logger, + Authority: pool.Authority.ToString(), + Reason: reason, + ConnectionId: connectionId); + } + + public static void LogConnectionOpened(ILogger logger, Connection connection, bool viaUpstreamProxy) + { + if (!logger.IsEnabled(LogLevel.Debug)) + return; + + var ssl = connection.SslInfo; + + ConnectionOpened(logger, + ConnectionId: connection.Id, + Authority: connection.Authority.ToString(), + RemoteIp: connection.RemoteAddress?.ToString() ?? string.Empty, + RemotePort: connection.Authority.Port, + LocalPort: connection.LocalPort, + HttpVersion: connection.HttpVersion ?? string.Empty, + Alpn: ssl?.NegotiatedApplicationProtocol, + TlsProtocol: ssl?.SslProtocol.ToString(), + CipherSuite: ssl?.NegotiatedCipherSuite.ToString(), + SniSent: connection.Authority.Secure ? connection.Authority.HostName : null, + TcpConnectMs: Ms(connection.TcpConnectionOpening, connection.TcpConnectionOpened), + TlsHandshakeMs: Ms(connection.SslNegotiationStart, connection.SslNegotiationEnd), + ProxyConnectMs: Ms(connection.ProxyConnectStart, connection.ProxyConnectEnd), + ViaUpstreamProxy: viaUpstreamProxy); + } + + private static double Ms(DateTime start, DateTime end) + { + return start == default || end == default ? 0 : (end - start).TotalMilliseconds; + } + } +#pragma warning restore SYSLIB1015 +} diff --git a/src/Fluxzy.Core/Logging/FluxzyLoggerScopes.cs b/src/Fluxzy.Core/Logging/FluxzyLoggerScopes.cs new file mode 100644 index 000000000..d2e12407b --- /dev/null +++ b/src/Fluxzy.Core/Logging/FluxzyLoggerScopes.cs @@ -0,0 +1,109 @@ +// Copyright 2021 - Haga Rakotoharivelo - https://github.com/haga-rak + +using System; +using System.Collections; +using System.Collections.Generic; +using Fluxzy.Core; +using Microsoft.Extensions.Logging; + +namespace Fluxzy.Logging +{ + internal static class FluxzyLoggerScopes + { + public static IDisposable? BeginConnectionScope( + ILogger logger, long proxyConnectionId, string downstreamRemote, string downstreamLocal) + { + return logger.BeginScope(new ConnectionScopeState(proxyConnectionId, downstreamRemote, downstreamLocal)); + } + + public static IDisposable? BeginExchangeScope(ILogger logger, Exchange exchange) + { + return logger.BeginScope(new ExchangeScopeState( + exchange.Id, + exchange.Authority.ToString(), + exchange.Method, + exchange.Path, + exchange.HttpVersion)); + } + } + + internal sealed class ConnectionScopeState : IReadOnlyList> + { + private readonly long _proxyConnectionId; + private readonly string _downstreamRemote; + private readonly string _downstreamLocal; + + public ConnectionScopeState(long proxyConnectionId, string downstreamRemote, string downstreamLocal) + { + _proxyConnectionId = proxyConnectionId; + _downstreamRemote = downstreamRemote; + _downstreamLocal = downstreamLocal; + } + + public int Count => 3; + + public KeyValuePair this[int index] => index switch { + 0 => new KeyValuePair("ProxyConnectionId", _proxyConnectionId), + 1 => new KeyValuePair("DownstreamRemote", _downstreamRemote), + 2 => new KeyValuePair("DownstreamLocal", _downstreamLocal), + _ => throw new ArgumentOutOfRangeException(nameof(index)) + }; + + public IEnumerator> GetEnumerator() + { + for (var i = 0; i < Count; i++) { + yield return this[i]; + } + } + + IEnumerator IEnumerable.GetEnumerator() => GetEnumerator(); + + public override string ToString() + { + return $"ProxyConnectionId={_proxyConnectionId} DownstreamRemote={_downstreamRemote} DownstreamLocal={_downstreamLocal}"; + } + } + + internal sealed class ExchangeScopeState : IReadOnlyList> + { + private readonly int _exchangeId; + private readonly string _authority; + private readonly string _method; + private readonly string _path; + private readonly string _httpVersion; + + public ExchangeScopeState(int exchangeId, string authority, string method, string path, string httpVersion) + { + _exchangeId = exchangeId; + _authority = authority; + _method = method; + _path = path; + _httpVersion = httpVersion; + } + + public int Count => 5; + + public KeyValuePair this[int index] => index switch { + 0 => new KeyValuePair("ExchangeId", _exchangeId), + 1 => new KeyValuePair("Authority", _authority), + 2 => new KeyValuePair("Method", _method), + 3 => new KeyValuePair("Path", _path), + 4 => new KeyValuePair("HttpVersion", _httpVersion), + _ => throw new ArgumentOutOfRangeException(nameof(index)) + }; + + public IEnumerator> GetEnumerator() + { + for (var i = 0; i < Count; i++) { + yield return this[i]; + } + } + + IEnumerator IEnumerable.GetEnumerator() => GetEnumerator(); + + public override string ToString() + { + return $"ExchangeId={_exchangeId} Authority={_authority} Method={_method} Path={_path} HttpVersion={_httpVersion}"; + } + } +} diff --git a/src/Fluxzy.Core/Logging/HeaderRedactor.cs b/src/Fluxzy.Core/Logging/HeaderRedactor.cs new file mode 100644 index 000000000..1559cc3a6 --- /dev/null +++ b/src/Fluxzy.Core/Logging/HeaderRedactor.cs @@ -0,0 +1,50 @@ +// Copyright 2021 - Haga Rakotoharivelo - https://github.com/haga-rak + +using System; +using System.Collections.Generic; +using System.Text; + +namespace Fluxzy.Logging +{ + internal static class HeaderRedactor + { + public static readonly HashSet DefaultRedactedHeaders = + new(StringComparer.OrdinalIgnoreCase) { + "Authorization", + "Proxy-Authorization", + "Cookie", + "Set-Cookie", + "X-Auth-Token" + }; + + public static string FormatHeaders( + IEnumerable? headers, FluxzySetting? setting) + { + if (headers == null) + return string.Empty; + + var includeSensitive = setting?.LogIncludeSensitiveHeaders ?? false; + var redactSet = setting?.LogRedactedHeaders ?? DefaultRedactedHeaders; + + var sb = new StringBuilder(); + + foreach (var h in headers) { + var name = h.Name.ToString(); + + if (sb.Length > 0) + sb.Append('\n'); + + sb.Append(name).Append('='); + + if (!includeSensitive && redactSet.Contains(name)) { + sb.Append(" - /// Trace everything, slow! - /// - /// - /// - public static void Trace(string message, TraceType traceType) - { - if (!EnableTracing) - return; - - lock (Lock) { - var consoleColor = Console.ForegroundColor; - - try - { - // get Color - var color = GetColor(traceType); - Console.WriteLine(message); - } - finally - { - Console.ForegroundColor = consoleColor; - } - } - - } - - public static void TraceException(Exception ex, string? message = null) - { - var builder = new StringBuilder(); - - if (!string.IsNullOrEmpty(message)) { - builder.AppendLine($"{message}: {ex.Message}"); - } - else - { - builder.AppendLine(ex.Message); - } - - Trace(builder.ToString(), TraceType.Error); - } - - public static void TraceWarning(string message) - { - Trace(message, TraceType.Error); - } - - public static void TraceInfo(string message) - { - Trace(message, TraceType.Info); - } - - private static ConsoleColor GetColor(TraceType traceType) - { - switch (traceType) { - case TraceType.Info: - return ConsoleColor.Blue; - case TraceType.Warning: - return ConsoleColor.Yellow; - case TraceType.Error: - return ConsoleColor.Red; - default: - return ConsoleColor.White; - } - } - } - - public enum TraceType - { - Info, - Warning, - Error - } -} diff --git a/src/Fluxzy.Core/Proxy.cs b/src/Fluxzy.Core/Proxy.cs index f6fdad810..6852dc345 100644 --- a/src/Fluxzy.Core/Proxy.cs +++ b/src/Fluxzy.Core/Proxy.cs @@ -16,13 +16,15 @@ using Fluxzy.Clients.Ssl.BouncyCastle; using Fluxzy.Clients.Ssl.SChannel; using Fluxzy.Core; +using Fluxzy.Logging; using Fluxzy.Misc; using Fluxzy.Misc.ResizableBuffers; -using Fluxzy.Misc.Traces; using Fluxzy.Rules; using Fluxzy.Rules.Actions; using Fluxzy.Rules.Filters; using Fluxzy.Writers; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Fluxzy { @@ -38,6 +40,8 @@ public class Proxy : IAsyncDisposable private readonly ProxyOrchestrator _proxyOrchestrator; private readonly ProxyRuntimeSetting _runTimeSetting; + private readonly ILogger _logger; + private long _nextProxyConnectionId; private volatile int _currentConcurrentCount; private bool _disposed; private List? _discoveryServices; @@ -52,14 +56,17 @@ public class Proxy : IAsyncDisposable /// The startup Setting /// The tcp connection provider, if null the default is used /// Use this authentication method instead of the one provided in FluxzySetting + /// Optional logger factory. When null, no logs are emitted. public Proxy( FluxzySetting startupSetting, ITcpConnectionProvider? tcpConnectionProvider = null, - ProxyAuthenticationMethod? proxyAuthenticationMethod = null) + ProxyAuthenticationMethod? proxyAuthenticationMethod = null, + ILoggerFactory? loggerFactory = null) : this(startupSetting, new CertificateProvider(startupSetting.CaCertificate, new InMemoryCertificateCache()), new DefaultCertificateAuthorityManager(), tcpConnectionProvider, - proxyAuthenticationMethod: proxyAuthenticationMethod) + proxyAuthenticationMethod: proxyAuthenticationMethod, + loggerFactory: loggerFactory) { } @@ -76,6 +83,7 @@ public Proxy( /// Add a custom DNS solver /// An external cancellation token /// Use this authentication method instead of the one provided in FluxzySetting + /// Optional logger factory. When null, no logs are emitted. /// public Proxy( FluxzySetting startupSetting, @@ -86,7 +94,8 @@ public Proxy( FromIndexIdProvider? idProvider = null, IDnsSolver? dnsSolver = null, CancellationTokenSource? externalCancellationSource = null, - ProxyAuthenticationMethod? proxyAuthenticationMethod = null) + ProxyAuthenticationMethod? proxyAuthenticationMethod = null, + ILoggerFactory? loggerFactory = null) { _certificateProvider = certificateProvider; _externalCancellationSource = externalCancellationSource; @@ -97,7 +106,9 @@ public Proxy( _downStreamConnectionProvider = new DownStreamConnectionProvider(StartupSetting.BoundPoints); - var secureConnectionManager = new SecureConnectionUpdater(certificateProvider, startupSetting.ServeH2); + var secureConnectionManager = new SecureConnectionUpdater( + certificateProvider, startupSetting.ServeH2, + (loggerFactory ?? NullLoggerFactory.Instance).CreateLogger()); if (StartupSetting.ArchivingPolicy.Type == ArchivingPolicyType.Directory && StartupSetting.ArchivingPolicy.Directory != null) { @@ -118,12 +129,15 @@ public Proxy( var poolBuilder = new PoolBuilder( new RemoteConnectionBuilder(ITimingProvider.Default, sslConnectionBuilder), ITimingProvider.Default, - Writer, dnsSolver ?? new DefaultDnsResolver()); + Writer, dnsSolver ?? new DefaultDnsResolver(), + loggerFactory); ExecutionContext = new ProxyExecutionContext(startupSetting); _runTimeSetting = new ProxyRuntimeSetting(startupSetting, ExecutionContext, tcpConnectionProvider1, - Writer, IdProvider, userAgentProvider); + Writer, IdProvider, userAgentProvider, loggerFactory, InstanceId); + + _logger = _runTimeSetting.GetLogger(); proxyAuthenticationMethod ??= ProxyAuthenticationMethodBuilder.Create(startupSetting.ProxyAuthentication); @@ -165,6 +179,14 @@ public Proxy( /// public string SessionIdentifier { get; } = DateTime.Now.ToString("yyyyMMdd-HHmmss"); + /// + /// A unique identifier for this proxy instance. Emitted as the + /// fluxzy.proxy.instance_id tag on every activity produced by + /// Fluxzy.Core, so OpenTelemetry consumers can correlate or + /// filter activities to a specific Proxy when several run in-process. + /// + public Guid InstanceId { get; } = Guid.NewGuid(); + /// /// Gets the collection of IP endpoints associated with this proxy. Returns null if the proxy is not started. /// @@ -241,6 +263,16 @@ private async ValueTask MainLoop() } } + private static string SafeRemoteEndPoint(TcpClient client) + { + try { + return client.Client.RemoteEndPoint?.ToString() ?? string.Empty; + } + catch { + return string.Empty; + } + } + private async void ProcessingConnection(TcpClient client) { var currentCount = Interlocked.Increment(ref _currentConcurrentCount); @@ -261,6 +293,15 @@ private async void ProcessingConnection(TcpClient client) var closeImmediately = FluxzySharedSetting.OverallMaxConcurrentConnections < currentCount; + var proxyConnectionId = Interlocked.Increment(ref _nextProxyConnectionId); + var remoteEp = client.Client.RemoteEndPoint?.ToString() ?? string.Empty; + var localEp = client.Client.LocalEndPoint?.ToString() ?? string.Empty; + + using var connectionScope = FluxzyLoggerScopes.BeginConnectionScope( + _logger, proxyConnectionId, remoteEp, localEp); + + FluxzyLogEvents.ClientConnectionAccepted(_logger, currentCount, closeImmediately); + await _proxyOrchestrator!.Operate(client, buffer, closeImmediately, _proxyHaltTokenSource.Token) .ConfigureAwait(false); } @@ -269,13 +310,8 @@ private async void ProcessingConnection(TcpClient client) } } catch (Exception ex) { - // We ignore any parsing errors that may block the proxy - // TODO : escalate from Serilog To Here - - if (D.EnableTracing) { - var message = $"Processing error {client.Client.RemoteEndPoint}"; - D.TraceException(ex, message); - } + var remote = SafeRemoteEndPoint(client); + FluxzyLogEvents.ConnectionProcessingError(_logger, ex, remote); } finally { Interlocked.Decrement(ref _currentConcurrentCount); diff --git a/src/Fluxzy/Commands/StartCommandBuilder.cs b/src/Fluxzy/Commands/StartCommandBuilder.cs index f683d8834..508b08c3d 100644 --- a/src/Fluxzy/Commands/StartCommandBuilder.cs +++ b/src/Fluxzy/Commands/StartCommandBuilder.cs @@ -17,10 +17,10 @@ using Fluxzy.Core.Pcap; using Fluxzy.Core.Pcap.Cli.Clients; using Fluxzy.Extensions; -using Fluxzy.Misc.Traces; using Fluxzy.Rules; using Fluxzy.Utils.NativeOps.SystemProxySetup; using Fluxzy.Cli.Commands.PrettyOutput; +using Microsoft.Extensions.Logging; namespace Fluxzy.Cli.Commands { @@ -75,7 +75,6 @@ public Command Build(CancellationToken cancellationToken) command.AddOption(StartCommandOptions.CreateBouncyCastleOption()); command.AddOption(StartCommandOptions.CreateTcpDumpOption()); command.AddOption(StartCommandOptions.CreateOutOfProcCaptureOption()); - command.AddOption(StartCommandOptions.CreateEnableTracingOption()); command.AddOption(StartCommandOptions.CreateSkipCertInstallOption()); command.AddOption(StartCommandOptions.CreateNoCertCacheOption()); command.AddOption(StartCommandOptions.CreateCertificateFileOption()); @@ -95,6 +94,7 @@ public Command Build(CancellationToken cancellationToken) command.AddOption(StartCommandOptions.CreateServeH2Option()); command.AddOption(StartCommandOptions.CreateEnableDiscoveryOption()); command.AddOption(StartCommandOptions.CreateProtoDirectoryOption()); + command.AddOption(StartCommandOptions.CreateTraceOption()); command.SetHandler(context => Run(context, cancellationToken)); @@ -126,7 +126,6 @@ public async Task Run(InvocationContext invocationContext, CancellationToken pro var requestBuffer = invocationContext.Value("request-buffer"); var maxConnectionPerHost = invocationContext.Value("max-upstream-connection"); var count = invocationContext.Value("max-capture-count"); - var trace = invocationContext.Value("trace"); var use502 = invocationContext.Value("use-502"); var proxyMode = invocationContext.Value("mode"); var modeReversePort = invocationContext.Value("mode-reverse-port"); @@ -138,10 +137,7 @@ public async Task Run(InvocationContext invocationContext, CancellationToken pro var serveH2 = invocationContext.Value("serve-h2"); var enableDiscovery = invocationContext.Value("enable-discovery"); var protoDirectories = invocationContext.Value>("proto-dir"); - - if (trace) { - D.EnableTracing = true; - } + var traceMode = invocationContext.Value("trace"); FluxzySharedSetting.Use528 = !use502; @@ -312,6 +308,8 @@ public async Task Run(InvocationContext invocationContext, CancellationToken pro var uaParserProvider = parseUserAgent ? new UaParserUserAgentInfoProvider() : null; var systemProxyManager = new SystemProxyRegistrationManager(new NativeProxySetterManager().Get()); + using var loggerFactory = CreateTraceLoggerFactory(traceMode); + // Scope owns the out-of-proc capture subprocess lifetime. It must be disposed // BEFORE PackDirectoryToFile runs so the subprocess closes its pcapng FileStreams // and flushes all buffered packet data to disk; otherwise small captures can sit @@ -329,7 +327,8 @@ public async Task Run(InvocationContext invocationContext, CancellationToken pro : ITcpConnectionProvider.Default) { await using (var proxy = new Proxy(proxyStartUpSetting, certificateProvider, new DefaultCertificateAuthorityManager(), tcpConnectionProvider, uaParserProvider, - externalCancellationSource: linkedTokenSource)) { + externalCancellationSource: linkedTokenSource, + loggerFactory: loggerFactory)) { var endPoints = proxy.Run(); @@ -415,6 +414,24 @@ await PackDirectoryToFile( } } + private static ILoggerFactory? CreateTraceLoggerFactory(TraceMode traceMode) + { + if (traceMode == TraceMode.None) { + return null; + } + + var minimumLevel = traceMode == TraceMode.Deep ? LogLevel.Trace : LogLevel.Debug; + + return LoggerFactory.Create(builder => { + builder.SetMinimumLevel(minimumLevel); + builder.AddFilter("Fluxzy", minimumLevel); + builder.AddSimpleConsole(options => { + options.SingleLine = true; + options.TimestampFormat = "HH:mm:ss.fff "; + }); + }); + } + private static bool ValidateSetting(InvocationContext invocationContext, FluxzySetting proxyStartUpSetting) { var validationResults = AggregateFluxzySettingAnalyzer.Instance.Validate(proxyStartUpSetting).ToList(); diff --git a/src/Fluxzy/Commands/StartCommandOptions.cs b/src/Fluxzy/Commands/StartCommandOptions.cs index 8a72d1e0b..0425fde4b 100644 --- a/src/Fluxzy/Commands/StartCommandOptions.cs +++ b/src/Fluxzy/Commands/StartCommandOptions.cs @@ -400,19 +400,6 @@ public static Option CreateRuleStdinOption() return option; } - public static Option CreateEnableTracingOption() - { - var option = new Option( - "--trace", - "Output trace on stdout"); - - option.AddAlias("-t"); - option.SetDefaultValue(false); - option.Arity = ArgumentArity.Zero; - - return option; - } - public static Option CreateEnableProcessTrackingOption() { var option = new Option( @@ -502,5 +489,39 @@ public static Option CreateEnableDiscoveryOption() return option; } + + public static Option CreateTraceOption() + { + var option = new Option( + "--trace", + result => { + if (result.Tokens.Count == 0) { + return TraceMode.Debug; + } + + var value = result.Tokens.First().Value; + + if (string.Equals(value, "deep", StringComparison.OrdinalIgnoreCase)) { + return TraceMode.Deep; + } + + if (string.Equals(value, "debug", StringComparison.OrdinalIgnoreCase)) { + return TraceMode.Debug; + } + + result.ErrorMessage = $"Invalid trace value '{value}'. Expected: deep (or omit value for debug)."; + + return TraceMode.None; + }); + + option.AddAlias("-t"); + option.Description = + "Emit Fluxzy diagnostic logs to the console. " + + "Without a value, logs at Debug level. Use '-t deep' for verbose (Trace) level."; + option.SetDefaultValue(TraceMode.None); + option.Arity = ArgumentArity.ZeroOrOne; + + return option; + } } } diff --git a/src/Fluxzy/Commands/TraceMode.cs b/src/Fluxzy/Commands/TraceMode.cs new file mode 100644 index 000000000..90398753a --- /dev/null +++ b/src/Fluxzy/Commands/TraceMode.cs @@ -0,0 +1,11 @@ +// Copyright 2021 - Haga Rakotoharivelo - https://github.com/haga-rak + +namespace Fluxzy.Cli.Commands +{ + public enum TraceMode + { + None = 0, + Debug, + Deep + } +} diff --git a/src/Fluxzy/fluxzy.csproj b/src/Fluxzy/fluxzy.csproj index d2f79a40c..e0bbc5e65 100644 --- a/src/Fluxzy/fluxzy.csproj +++ b/src/Fluxzy/fluxzy.csproj @@ -33,6 +33,7 @@ + diff --git a/test/Fluxzy.Benchmarks/WindowSizeBookingBenchmark.cs b/test/Fluxzy.Benchmarks/WindowSizeBookingBenchmark.cs index bfc8725bb..b2d0a30ef 100644 --- a/test/Fluxzy.Benchmarks/WindowSizeBookingBenchmark.cs +++ b/test/Fluxzy.Benchmarks/WindowSizeBookingBenchmark.cs @@ -20,7 +20,6 @@ public class WindowSizeBookingBenchmark private const int WindowSize = 1 << 24; // 16 MB — large enough to avoid slow-path waits private const int BatchFrames = 4; // matches ServerStreamWorker.BatchFrames - private H2Logger _logger = null!; private WindowSizeHolder _streamHolder = null!; private WindowSizeHolder _overallHolder = null!; @@ -31,7 +30,6 @@ public class WindowSizeBookingBenchmark public void Setup() { var authority = new Authority("bench.local", 443, true); - _logger = new H2Logger(authority, connectionId: 0, active: false); } [IterationSetup] @@ -41,8 +39,8 @@ public void IterationSetup() _streamHolder?.Dispose(); _overallHolder?.Dispose(); - _streamHolder = new WindowSizeHolder(_logger, WindowSize, streamIdentifier: 1); - _overallHolder = new WindowSizeHolder(_logger, WindowSize, streamIdentifier: 0); + _streamHolder = new WindowSizeHolder(WindowSize, streamIdentifier: 1); + _overallHolder = new WindowSizeHolder(WindowSize, streamIdentifier: 0); } [IterationCleanup] @@ -94,7 +92,7 @@ public async Task BookTwoStage_Contended() for (var t = 0; t < ConcurrentTasks; t++) { // Each task gets its own stream holder but shares the overall holder. - var streamHolder = new WindowSizeHolder(_logger, WindowSize, streamIdentifier: t + 10); + var streamHolder = new WindowSizeHolder(WindowSize, streamIdentifier: t + 10); var framesPerTask = 1024 / ConcurrentTasks; tasks[t] = Task.Run(async () => { @@ -165,7 +163,7 @@ public async Task BookTwoStage_BatchedContended() var tasks = new Task[ConcurrentTasks]; for (var t = 0; t < ConcurrentTasks; t++) { - var streamHolder = new WindowSizeHolder(_logger, WindowSize, streamIdentifier: t + 10); + var streamHolder = new WindowSizeHolder(WindowSize, streamIdentifier: t + 10); var framesPerTask = 1024 / ConcurrentTasks; tasks[t] = Task.Run(async () => { diff --git a/test/Fluxzy.Tests/Cases/ActivitySourceTests.cs b/test/Fluxzy.Tests/Cases/ActivitySourceTests.cs new file mode 100644 index 000000000..e07b88be3 --- /dev/null +++ b/test/Fluxzy.Tests/Cases/ActivitySourceTests.cs @@ -0,0 +1,71 @@ +// Copyright 2021 - Haga Rakotoharivelo - https://github.com/haga-rak + +using System; +using System.Collections.Concurrent; +using System.Diagnostics; +using System.Linq; +using System.Net; +using System.Threading.Tasks; +using Fluxzy.Tests._Fixtures; +using Xunit; + +namespace Fluxzy.Tests.Cases +{ + public class ActivitySourceTests + { + [Fact] + public async Task Activity_Is_Emitted_Per_Exchange_With_Otel_Tags() + { + var started = new ConcurrentBag(); + var stopped = new ConcurrentBag(); + + using var listener = new ActivityListener { + ShouldListenTo = source => source.Name == "Fluxzy.Core", + Sample = (ref ActivityCreationOptions _) => + ActivitySamplingResult.AllDataAndRecorded, + SampleUsingParentId = (ref ActivityCreationOptions _) => + ActivitySamplingResult.AllDataAndRecorded, + ActivityStarted = started.Add, + ActivityStopped = stopped.Add + }; + + ActivitySource.AddActivityListener(listener); + + await using var setup = await ProxiedHostSetup.Create(); + + var response = await setup.Client.GetAsync("/hello"); + Assert.Equal(HttpStatusCode.OK, response.StatusCode); + await response.Content.ReadAsByteArrayAsync(); + response.Dispose(); + + // ActivitySource/ActivityListener are process-global, so concurrent test classes + // running in parallel may emit activities into the same listener. Match only the + // activity produced by this test's Proxy via its unique instance id. + var instanceId = setup.Proxy.InstanceId; + bool IsThisExchange(Activity a) => + a.GetTagItem("fluxzy.proxy.instance_id") is Guid id && id == instanceId; + + // The exchange-completion event drains the response body asynchronously, + // so give the in-flight activity stop a brief window before asserting. + for (var i = 0; i < 50 && !stopped.Any(IsThisExchange); i++) + await Task.Delay(50); + + Assert.True(started.Any(IsThisExchange), + $"No Fluxzy.Core activity started for {setup.BaseUrl}. See: started={started.Count} stopped={stopped.Count}"); + + var activity = stopped.FirstOrDefault(IsThisExchange); + Assert.NotNull(activity); + Assert.Equal(ActivityKind.Server, activity.Kind); + Assert.Equal("HTTP GET", activity.OperationName); + + Assert.Equal("GET", activity.GetTagItem("http.request.method")); + Assert.NotNull(activity.GetTagItem("url.full")); + Assert.NotNull(activity.GetTagItem("server.address")); + Assert.Equal(200, activity.GetTagItem("http.response.status_code")); + Assert.NotNull(activity.GetTagItem("network.protocol.version")); + Assert.NotNull(activity.GetTagItem("fluxzy.exchange_id")); + Assert.NotNull(activity.GetTagItem("fluxzy.pool.type")); + Assert.NotNull(activity.GetTagItem("fluxzy.dns.duration_ms")); + } + } +} diff --git a/test/Fluxzy.Tests/Cases/ExchangeEnvelopeRedactionTests.cs b/test/Fluxzy.Tests/Cases/ExchangeEnvelopeRedactionTests.cs new file mode 100644 index 000000000..e313ba4ad --- /dev/null +++ b/test/Fluxzy.Tests/Cases/ExchangeEnvelopeRedactionTests.cs @@ -0,0 +1,153 @@ +// Copyright 2021 - Haga Rakotoharivelo - https://github.com/haga-rak + +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Linq; +using System.Net; +using System.Threading.Tasks; +using Fluxzy.Rules.Actions; +using Fluxzy.Rules.Filters; +using Fluxzy.Tests._Fixtures; +using Microsoft.Extensions.Logging; +using Xunit; + +namespace Fluxzy.Tests.Cases +{ + public class ExchangeEnvelopeRedactionTests + { + [Fact] + public async Task Envelope_Redacts_Authorization_By_Default() + { + var factory = new TestLoggerFactory(LogLevel.Trace); + + await using var host = await InProcessHost.Create(); + + var setting = FluxzySetting.CreateLocalRandomPort(); + setting.AddAlterationRules(new SkipRemoteCertificateValidationAction(), AnyFilter.Default); + + await using var proxy = new Proxy(setting, loggerFactory: factory); + var endPoint = proxy.Run().First(); + + using var client = Socks5ClientFactory.Create(endPoint); + client.BaseAddress = new Uri(host.BaseUrl); + client.DefaultRequestHeaders.Add("Authorization", "Bearer secret-token-12345"); + + var response = await client.GetAsync("/hello"); + Assert.Equal(HttpStatusCode.OK, response.StatusCode); + await response.Content.ReadAsByteArrayAsync(); + response.Dispose(); + + var envelope = await WaitForEvent(factory, eventId: 1099); + Assert.NotNull(envelope); + + var requestHeaders = envelope.Properties.GetValueOrDefault("RequestHeaders")?.ToString(); + Assert.NotNull(requestHeaders); + Assert.Contains("Authorization=", requestHeaders); + Assert.Contains(" WaitForEvent(TestLoggerFactory factory, int eventId) + { + for (var i = 0; i < 50; i++) { + var match = factory.Logger.Logs.FirstOrDefault(l => l.EventId.Id == eventId); + if (match != null) return match; + await Task.Delay(50); + } + return null; + } + } + + internal sealed class CapturedLog + { + public LogLevel Level { get; init; } + public EventId EventId { get; init; } + public string Message { get; init; } = string.Empty; + public Dictionary Properties { get; init; } = new(); + } + + internal sealed class TestLogger : ILogger + { + private readonly LogLevel _minLevel; + + public TestLogger(LogLevel minLevel) + { + _minLevel = minLevel; + } + + public ConcurrentBag Logs { get; } = new(); + + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + public bool IsEnabled(LogLevel logLevel) => logLevel >= _minLevel; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, + Func formatter) + { + if (!IsEnabled(logLevel)) return; + + var props = new Dictionary(); + if (state is IEnumerable> kvs) { + foreach (var kv in kvs) { + props[kv.Key] = kv.Value; + } + } + + Logs.Add(new CapturedLog { + Level = logLevel, + EventId = eventId, + Message = formatter(state, exception), + Properties = props + }); + } + } + + internal sealed class TestLoggerFactory : ILoggerFactory + { + public TestLogger Logger { get; } + + public TestLoggerFactory(LogLevel minLevel) + { + Logger = new TestLogger(minLevel); + } + + public ILogger CreateLogger(string categoryName) => Logger; + public void AddProvider(ILoggerProvider provider) { } + public void Dispose() { } + } +} diff --git a/test/Fluxzy.Tests/UnitTests/H2Client/H2ConnectionPoolGoAwayTests.cs b/test/Fluxzy.Tests/UnitTests/H2Client/H2ConnectionPoolGoAwayTests.cs index 88fb9958a..2bb6b0d85 100644 --- a/test/Fluxzy.Tests/UnitTests/H2Client/H2ConnectionPoolGoAwayTests.cs +++ b/test/Fluxzy.Tests/UnitTests/H2Client/H2ConnectionPoolGoAwayTests.cs @@ -263,7 +263,6 @@ private static StreamPool CreateBareStreamPool() { var authority = new Authority("test.local", 443, true); var setting = new H2StreamSetting(); - var logger = new H2Logger(authority, -1); var hpackEncoder = new HPackEncoder( new EncodingContext(ArrayPoolMemoryProvider.Default)); @@ -271,7 +270,7 @@ private static StreamPool CreateBareStreamPool() new DecodingContext(authority, ArrayPoolMemoryProvider.Default)); var headerEncoder = new HeaderEncoder(hpackEncoder, hpackDecoder, setting); - var overallWindow = new WindowSizeHolder(logger, setting.OverallWindowSize, 0); + var overallWindow = new WindowSizeHolder(setting.OverallWindowSize, 0); UpStreamChannel noopChannel = (ref WriteTask _) => { }; @@ -279,7 +278,6 @@ private static StreamPool CreateBareStreamPool() connectionId: 1, authority: authority, setting: setting, - logger: logger, headerEncoder: headerEncoder, upStreamChannel: noopChannel, overallWindowSizeHolder: overallWindow);