diff --git a/ReleaseNotes/version2.2.md b/ReleaseNotes/version2.2.md index 0789c82b..0802aa84 100644 --- a/ReleaseNotes/version2.2.md +++ b/ReleaseNotes/version2.2.md @@ -1,6 +1,23 @@ # Release Notes # +2.2.13.2.6 +Bug fix validation : Reverting the code to make use of dotnet 9 + +2.2.13.2.5 +Bug fix: Add empty token check +Bug fix: Regression fix for auth settings + +2.2.13.2.3 +Bug fix: Potential authorization header corruption + +2.2.13.2.2 +Bug fix: capture client read errors + +2.2.13.2.1 +Bug fix: refresh tokens 200ms before expiration, use tokens with at least 100ms, use atomic token list, reduce error time to 5s + 2.2.13.2 +Added Lifetime-Attempts, Policy-Cycle-Counter, Lifetime-Policy-Counter to Event Data Proxy: * Update the default for the console to not log custom events diff --git a/dotnet/runfile-discovery/SimpleL7Proxy-a87d91e5bfed11b838936e3ae4b84770b5843c6aa947b74117c730e2f81a7c63/cache.staging.json b/dotnet/runfile-discovery/SimpleL7Proxy-a87d91e5bfed11b838936e3ae4b84770b5843c6aa947b74117c730e2f81a7c63/cache.staging.json new file mode 100644 index 00000000..14ff13a4 --- /dev/null +++ b/dotnet/runfile-discovery/SimpleL7Proxy-a87d91e5bfed11b838936e3ae4b84770b5843c6aa947b74117c730e2f81a7c63/cache.staging.json @@ -0,0 +1 @@ +{"WorkspacePath":"/workspaces/SimpleL7Proxy","LastWalkTimeUtc":"0001-01-01T00:00:00+00:00","FileBasedAppFullPaths":[],"DirectoriesContainingCsproj":["/workspaces/SimpleL7Proxy/src/ChatTester","/workspaces/SimpleL7Proxy/src/HealthProbe","/workspaces/SimpleL7Proxy/src/RequestAPI","/workspaces/SimpleL7Proxy/src/Shared","/workspaces/SimpleL7Proxy/src/Shared-parser","/workspaces/SimpleL7Proxy/src/SimpleL7Proxy","/workspaces/SimpleL7Proxy/src/StreamingMicroService","/workspaces/SimpleL7Proxy/test/eventHub/reader","/workspaces/SimpleL7Proxy/test/eventHub/writeToStorage","/workspaces/SimpleL7Proxy/test/EventHubMonitorTests","/workspaces/SimpleL7Proxy/test/generator/generator_one","/workspaces/SimpleL7Proxy/test/identity-test/dotnet","/workspaces/SimpleL7Proxy/test/identity-test/tokenserver","/workspaces/SimpleL7Proxy/test/LLMSimulator","/workspaces/SimpleL7Proxy/test/nullserver/dotnet","/workspaces/SimpleL7Proxy/test/QueueBenchmarks","/workspaces/SimpleL7Proxy/test/RegressionTests","/workspaces/SimpleL7Proxy/test/servicebus/client","/workspaces/SimpleL7Proxy/test/servicebus/MI-Send","/workspaces/SimpleL7Proxy/test/StorageBlob"]} \ No newline at end of file diff --git a/src/Shared-parser/Shared-parser.csproj b/src/Shared-parser/Shared-parser.csproj index 2c88a408..281f33dc 100644 --- a/src/Shared-parser/Shared-parser.csproj +++ b/src/Shared-parser/Shared-parser.csproj @@ -1,6 +1,6 @@ - net10.0 + net9.0 enable enable diff --git a/src/Shared-parser/StreamProcessor/JsonStreamProcessor.cs b/src/Shared-parser/StreamProcessor/JsonStreamProcessor.cs index 9636e710..9d145133 100644 --- a/src/Shared-parser/StreamProcessor/JsonStreamProcessor.cs +++ b/src/Shared-parser/StreamProcessor/JsonStreamProcessor.cs @@ -92,7 +92,6 @@ public override async Task CopyToAsync(System.Net.Http.HttpContent sourceContent currentIndex = (currentIndex + 1) % MaxLines; // Wrap around lineCount++; } - await t.ConfigureAwait(false); } @@ -159,7 +158,7 @@ public override async Task CopyToAsync(System.Net.Http.HttpContent sourceContent _logger?.LogDebug("Searching for usage and background request patterns in last lines"); // Loop through lines starting from most recent, going backwards - for (int i = 0; i < validLines.Length; i++) + for (int i = validLines.Length - 1; i >= 0; i--) { var line = validLines[i]; if (line.IndexOf("usage", StringComparison.OrdinalIgnoreCase) >= 0) diff --git a/src/Shared-parser/StreamProcessor/MultiAllUsageProcessor.cs b/src/Shared-parser/StreamProcessor/MultiAllUsageProcessor.cs index a837d2a3..5cebcba0 100644 --- a/src/Shared-parser/StreamProcessor/MultiAllUsageProcessor.cs +++ b/src/Shared-parser/StreamProcessor/MultiAllUsageProcessor.cs @@ -16,7 +16,7 @@ public class MultiLineAllUsageProcessor : JsonStreamProcessor @"""(?:[uU]sage|[uU]sage[mM]etadata)"":\s*(\{(?:[^{}]|(?\{)|(?<-open>\}))*(?(open)(?!))\})", RegexOptions.Singleline | RegexOptions.Compiled); - protected override int MaxLines => 100; + protected override int MaxLines => 50; protected override int MinLineLength => 1; /// diff --git a/src/SimpleL7Proxy/Backend/BackendTokenProvider.cs b/src/SimpleL7Proxy/Backend/BackendTokenProvider.cs index 84be4b55..f25f89e8 100644 --- a/src/SimpleL7Proxy/Backend/BackendTokenProvider.cs +++ b/src/SimpleL7Proxy/Backend/BackendTokenProvider.cs @@ -1,4 +1,5 @@ using System; +using System.Collections.Concurrent; using System.Threading; using System.Threading.Tasks; using Azure.Core; @@ -11,10 +12,11 @@ namespace SimpleL7Proxy.Backend { public class BackendTokenProvider : IHostedService, IReadinessParticipant { + private static readonly TimeSpan _tokenExpiryBuffer = TimeSpan.FromMilliseconds(100); + private static readonly TimeSpan _tokenRefreshExpiryBuffer = TimeSpan.FromMilliseconds(200); public ReadinessParticipantEnum Participant => ReadinessParticipantEnum.BackendTokens; public ReadinessRegistry Readiness { get; } - private readonly Dictionary _tokenDict = new(); - private readonly Dictionary _tokenExpiryDict = new(); + private readonly ConcurrentDictionary _tokenDict = new(); private readonly HashSet _audiences = new(); private readonly Dictionary _refreshTasks = new(); private static CancellationToken _cancellationToken = CancellationToken.None; @@ -60,15 +62,17 @@ public async Task OAuth2Token(string? audience = null) { if (string.IsNullOrEmpty(audience)) return string.Empty; - if (!_tokenDict.ContainsKey(audience) || _tokenExpiryDict[audience] < DateTime.UtcNow) + while (true) { - // Wait for token to be refreshed - while (!_tokenDict.ContainsKey(audience) || _tokenExpiryDict[audience] < DateTime.UtcNow) + if (_tokenDict.TryGetValue(audience, out var token) + && token.ExpiresOn > DateTimeOffset.UtcNow.Add(_tokenExpiryBuffer) + && !string.IsNullOrWhiteSpace(token.Token)) { - await Task.Delay(100).ConfigureAwait(false); + return token.Token; } + + await Task.Delay(100).ConfigureAwait(false); } - return _tokenDict[audience].Token ?? ""; } public void StartTokenRefresh() @@ -93,8 +97,22 @@ private void StartAudienceRefreshTask(string audience) { var tokenRequestContext = new TokenRequestContext(new[] { audience }); var token = await credential.GetTokenAsync(tokenRequestContext, _cancellationToken); + if (string.IsNullOrWhiteSpace(token.Token)) + { + new ProxyEvent() + { + Type = EventType.Exception, + ["Error"] = "EmptyToken", + ["Message"] = $"OAuth2 token refresh returned an empty token for audience: {audience}, expires: {token.ExpiresOn}", + ["Audience"] = audience, + ["ExpiresOn"] = token.ExpiresOn.ToString() + }.SendEvent(); + + await Task.Delay(500, _cancellationToken); + continue; + } + _tokenDict[audience] = token; - _tokenExpiryDict[audience] = token.ExpiresOn; this.RegisterReady(); // idempotent — first successful fetch satisfies the gate _logger.LogInformation($"[TOKEN] Refreshed token for audience: {audience}, expires: {token.ExpiresOn}"); new ProxyEvent() @@ -105,13 +123,13 @@ private void StartAudienceRefreshTask(string audience) ["ExpiresOn"] = token.ExpiresOn.ToString() }.SendEvent(); - var delay = Math.Max(0, (token.ExpiresOn - DateTime.UtcNow).TotalMilliseconds - 100); + var delay = Math.Max(0, (token.ExpiresOn - DateTimeOffset.UtcNow - _tokenRefreshExpiryBuffer).TotalMilliseconds); await Task.Delay((int)delay, _cancellationToken); } catch (Exception ex) { _logger.LogError($"[TOKEN] Error refreshing token for audience {audience}: {ex.Message}"); - await Task.Delay(10000, _cancellationToken); // Wait 10s before retry + await Task.Delay(5000, _cancellationToken); // Wait 5s before retry } } } diff --git a/src/SimpleL7Proxy/Backend/HostConfig.cs b/src/SimpleL7Proxy/Backend/HostConfig.cs index 16925480..c96f2683 100644 --- a/src/SimpleL7Proxy/Backend/HostConfig.cs +++ b/src/SimpleL7Proxy/Backend/HostConfig.cs @@ -185,8 +185,13 @@ public static void Initialize(BackendTokenProvider tokenProvider, ILogger logger /// public HostConfig(string hostname, string? probepath = "", string? ip = null)//, string? audience = "") { + + // were legacy oauth settings set? + var envUseOauth = Environment.GetEnvironmentVariable("UseOAuth")?.Trim().Equals("true", StringComparison.OrdinalIgnoreCase) ?? false; + var envAudience = Environment.GetEnvironmentVariable("OAuthAudience")?.Trim(); + _logger?.LogDebug("[CONFIGS] Configuring backend host: {hostname}", hostname); - ParsedConfig = TryParseConfig(hostname, probepath, ip);//, audience); + ParsedConfig = TryParseConfig(hostname, probepath, ip, envUseOauth, envAudience); // parse the host, protocol and port Uri uri = new Uri(ParsedConfig.Host); @@ -228,7 +233,7 @@ public HostConfig(string hostname, string? probepath = "", string? ip = null)//, } - private static ParsedConfig TryParseConfig(string hostname, string? probepath, string? ip)//, string? audience = "") + private static ParsedConfig TryParseConfig(string hostname, string? probepath, string? ip, bool useOauth = false, string? audience = "") /// /// Parses a backend configuration string into a ParsedConfig struct. /// @@ -241,8 +246,8 @@ private static ParsedConfig TryParseConfig(string hostname, string? probepath, s IpAddr = ip ?? "", PartialPath = "/", StripPrefix = true, - AuthMode = AuthModeEnum.None, - Audience = "", + AuthMode = useOauth ? AuthModeEnum.OAuth2 : AuthModeEnum.None, + Audience = audience, ApiKey = "", ApiKeyHeader = "api-key", UsesRetryAfter = true diff --git a/src/SimpleL7Proxy/Config/ProxyConfig.cs b/src/SimpleL7Proxy/Config/ProxyConfig.cs index 289c3162..de69546b 100644 --- a/src/SimpleL7Proxy/Config/ProxyConfig.cs +++ b/src/SimpleL7Proxy/Config/ProxyConfig.cs @@ -64,7 +64,7 @@ public class ProxyConfig [ConfigOption("Logging:LogToConsole")] public List LogToConsole { get; set; } = ["*", "-custom"]; [ConfigOption("Logging:LogToEvents")] - public List LogToEvents { get; set; } = ["async","backend","probe","circuitbreaker","custom","exception","profile","proxy","enqueued","auth"]; + public List LogToEvents { get; set; } = ["async","exception","backend","probe","circuitbreaker","custom","exception","profile","proxy","enqueued","auth"]; // ── Profiles ── [ConfigOption("Profiles:Auth:ConfigUrl")] diff --git a/src/SimpleL7Proxy/Constants.cs b/src/SimpleL7Proxy/Constants.cs index f639131b..bebb6644 100644 --- a/src/SimpleL7Proxy/Constants.cs +++ b/src/SimpleL7Proxy/Constants.cs @@ -15,7 +15,7 @@ public static class Constants public const string Random = "random"; public const string Server = "simplel7proxy"; - public const string VERSION = "2.2.13"; + public const string VERSION = "2.2.13.2.6"; public const int AnyPriority = -1; diff --git a/src/SimpleL7Proxy/Events/EventDataBuilder.cs b/src/SimpleL7Proxy/Events/EventDataBuilder.cs index 851ce956..ab0260b1 100644 --- a/src/SimpleL7Proxy/Events/EventDataBuilder.cs +++ b/src/SimpleL7Proxy/Events/EventDataBuilder.cs @@ -71,9 +71,16 @@ public void PopulateProxyEventData(RequestData request, ProxyData proxyData) eventData["Url"] = request.FullURL; var timeTaken = DateTime.UtcNow - request.EnqueueTime; eventData.Duration = timeTaken; + // TTFB-Latency = time from enqueue to backend response headers received. + // Total-Latency is overwritten later in StampFinalLatency() (called after + // Context.Response.OutputStream.Close()) so it captures the full proxy-side send time. + eventData["TTFB-Latency"] = timeTaken.TotalMilliseconds.ToString("F3"); eventData["Total-Latency"] = timeTaken.TotalMilliseconds.ToString("F3"); eventData["Attempts"] = request.BackendAttempts.ToString(); - + eventData["Lifetime-Attempts"] = request.LifetimeBackendAttempts.ToString(); + eventData["Policy-Cycle-Counter"] = request.PolicyCycleCounter.ToString(); + eventData["Lifetime-Policy-Counter"] = request.LifetimePolicyCycleCounter.ToString(); + if (proxyData != null) { eventData["Backend-Host"] = !string.IsNullOrEmpty(proxyData.BackendHostname) @@ -141,6 +148,9 @@ public void PopulateHeaderEventData(RequestData request, System.Collections.Spec /// /// Populates final event data with response information and incomplete requests. + /// Total-Latency is intentionally NOT stamped here — it is stamped later in + /// StampFinalLatency(), after the response output stream has been closed, so + /// the value includes the full proxy-side send time. /// public void PopulateFinalEventData(RequestData request, HttpListenerContext? context) { @@ -156,4 +166,19 @@ public void PopulateFinalEventData(RequestData request, HttpListenerContext? con _logger.LogTrace("Populated final event data for request {Guid}", request.Guid); } + + /// + /// Stamps Total-Latency and Duration with the time measured after the response + /// output stream has been fully closed. Call this immediately before Cleanup()/SendEvent() + /// so the event captures the true proxy-side send completion time. + /// + public void StampFinalLatency(RequestData request) + { + var trueLatency = DateTime.UtcNow - request.EnqueueTime; + request.EventData["Total-Latency"] = trueLatency.TotalMilliseconds.ToString("F3"); + request.EventData.Duration = trueLatency; + + _logger.LogTrace("Stamped final Total-Latency {Ms}ms for request {Guid}", + trueLatency.TotalMilliseconds.ToString("F3"), request.Guid); + } } diff --git a/src/SimpleL7Proxy/Proxy/ProxyWorker.cs b/src/SimpleL7Proxy/Proxy/ProxyWorker.cs index f2df4bb0..83d44409 100644 --- a/src/SimpleL7Proxy/Proxy/ProxyWorker.cs +++ b/src/SimpleL7Proxy/Proxy/ProxyWorker.cs @@ -1,6 +1,7 @@ using System.Net; using System.Net.Http.Headers; using System.Net.Sockets; +using System.Globalization; using System.Text; using System.Text.Json; using Microsoft.Extensions.Logging; @@ -424,6 +425,38 @@ public async Task TaskRunnerAsync() _wrkCntxt.RequeueWorker.DelayAsync(incomingRequest, e.RetryAfter); } + catch (S7PClientReadException e) + { + _lifecycleManager.TransitionToFailed(incomingRequest, HttpStatusCode.BadRequest, e.Message); + var failedRequest = e.Request; + var listenerRequest = failedRequest.Context?.Request; + var innerException = e.InnerException ?? e; + var declaredContentLength = listenerRequest?.ContentLength64 ?? -1; + + eventData.Status = HttpStatusCode.BadRequest; + eventData["Error"] = "Client Read Exception"; + eventData["ErrorDetails"] = innerException.Message; + eventData["ClientRead-ExceptionType"] = innerException.GetType().FullName ?? innerException.GetType().Name; + eventData["ClientRead-ListenerErrorCode"] = innerException is HttpListenerException listenerException + ? listenerException.ErrorCode.ToString(CultureInfo.InvariantCulture) + : "N/A"; + eventData["ClientRead-DeclaredContentLength"] = declaredContentLength.ToString(CultureInfo.InvariantCulture); + eventData["ClientRead-BytesRead"] = failedRequest.BodyReadBytes.ToString(CultureInfo.InvariantCulture); + eventData["ClientRead-ReadDurationMs"] = failedRequest.BodyReadDurationMilliseconds.ToString("F3", CultureInfo.InvariantCulture); + eventData["ClientRead-TransferEncoding"] = failedRequest.Headers["Transfer-Encoding"] ?? "N/A"; + eventData.Type = EventType.Exception; + eventData.Exception = e; + + if (lcontext != null) + { + await WriteErrorToClientAsync( + lcontext, + HttpStatusCode.BadRequest, + e.Message, + eventData, + incomingRequest.Guid); + } + } catch (ProxyErrorException e) { _lifecycleManager.TransitionToFailed(incomingRequest, e.StatusCode, e.Message); @@ -555,6 +588,22 @@ public async Task TaskRunnerAsync() if (workerState != "Cleanup") eventData["WorkerState"] = workerState; + // Close the response output stream now so Total-Latency captures + // the full proxy-side send time, including the final TCP flush. + // Stamp AFTER close, BEFORE Cleanup()/SendEvent(). + if (!incomingRequest.AsyncTriggered && incomingRequest.Context != null) + { + try + { + incomingRequest.Context.Response.OutputStream.Close(); + } + catch (Exception) + { + // Stream may already be closed/disposed — safe to ignore. + } + } + _eventDataBuilder.StampFinalLatency(incomingRequest); + incomingRequest.Cleanup(); try @@ -927,27 +976,6 @@ public async Task ProxyToBackEndAsync(RequestData request) // requestAttempt.Uri = request.Context!.Request.Url!; // else requestAttempt.Uri = new Uri(modifiedPath); - - - switch (host.Config.AuthMode) - { - case AuthModeEnum.OAuth2: - // Get a token - var oaToken = await host.Config.OAuth2Token().ConfigureAwait(false); - if (request.Debug) - { - _logger.LogDebug("OAuth Token retrieved for backend {BackendHost}", host.Host); - } - // Set the token in the headers - request.Headers.Set("Authorization", $"Bearer {oaToken}"); - break; - case AuthModeEnum.ApiKey: - // Set the API key in the headers - request.Headers.Set(host.Config.ApiKeyHeader, host.Config.ApiKey); - break; - } - - requestState = "Calc ExpiresAt"; // Validate request hasn't expired @@ -963,7 +991,15 @@ public async Task ProxyToBackEndAsync(RequestData request) requestState = "Cache Body"; // Read the body stream once and reuse it - byte[] bodyBytes = await request.CacheBodyAsync().ConfigureAwait(false); + byte[] bodyBytes; + try + { + bodyBytes = await request.CacheBodyAsync().ConfigureAwait(false); + } + catch (Exception ex) + { + throw new S7PClientReadException("Unable to read request body: " + ex.Message, request, ex); + } if (request.runAsync && !request.AsyncTriggered && @@ -1017,6 +1053,28 @@ public async Task ProxyToBackEndAsync(RequestData request) //proxyRequest.Headers.ConnectionClose = true; + switch (host.Config.AuthMode) + { + case AuthModeEnum.OAuth2: + // Get a token + var oaToken = await host.Config.OAuth2Token().ConfigureAwait(false); + if (request.Debug) + { + _logger.LogDebug("OAuth Token retrieved for backend {BackendHost}", host.Host); + } + + // Set the token in the headers + proxyRequest.Headers.Authorization = + new AuthenticationHeaderValue("Bearer", oaToken); + + break; + case AuthModeEnum.ApiKey: + // Set the API key in the headers + proxyRequest.Headers.Remove(host.Config.ApiKeyHeader); + proxyRequest.Headers.TryAddWithoutValidation(host.Config.ApiKeyHeader, host.Config.ApiKey); + break; + } + // Log request headers if debugging is enabled if (request.Debug) { @@ -1190,6 +1248,12 @@ public async Task ProxyToBackEndAsync(RequestData request) } } } + catch (S7PClientReadException) + { + TriggerHostCB = false; + intCode = (int)HttpStatusCode.BadRequest; + throw; + } catch (OutOfMemoryException oomEx) { TriggerHostCB = false; diff --git a/src/SimpleL7Proxy/Proxy/S7PClientReadException.cs b/src/SimpleL7Proxy/Proxy/S7PClientReadException.cs new file mode 100644 index 00000000..da0c2c88 --- /dev/null +++ b/src/SimpleL7Proxy/Proxy/S7PClientReadException.cs @@ -0,0 +1,28 @@ +namespace SimpleL7Proxy.Proxy; + +// This class represents the request received from the upstream client. +public class S7PClientReadException : Exception, IDisposable +{ + public RequestData Request { get; } + + public S7PClientReadException(string message, RequestData request, Exception innerException) + : base(message, innerException) + { + Request = request; + } + + public void Dispose() + { + // Dispose of unmanaged resources here + } + void IDisposable.Dispose() + { + // TODO: Dispose of unmanaged resources here + } + + public ValueTask DisposeAsync() + { + ((IDisposable)this).Dispose(); + return ValueTask.CompletedTask; + } +} diff --git a/src/SimpleL7Proxy/RequestData.cs b/src/SimpleL7Proxy/RequestData.cs index 04489472..83b04292 100644 --- a/src/SimpleL7Proxy/RequestData.cs +++ b/src/SimpleL7Proxy/RequestData.cs @@ -1,5 +1,6 @@ using System; using System.Collections.Concurrent; +using System.Diagnostics; using System.IO; using System.Net; using System.Threading.Tasks; @@ -201,6 +202,8 @@ public ServiceBusMessageStatusEnum SBStatus public bool Debug { get; set; } public bool SkipDispose { get; set; } = false; public byte[]? BodyBytes { get; set; } = null; + public long BodyReadBytes { get; private set; } + public double BodyReadDurationMilliseconds { get; private set; } public DateTime DequeueTime { get; set; } public DateTime EnqueueTime { get; set; } public DateTime ExpiresAt { get; set; } @@ -386,8 +389,17 @@ public async Task CacheBodyAsync() // Read the body stream once and reuse it using (MemoryStream ms = new()) { - await Body.CopyToAsync(ms); - BodyBytes = ms.ToArray(); + var bodyReadStart = Stopwatch.GetTimestamp(); + try + { + await Body.CopyToAsync(ms).ConfigureAwait(false); + BodyBytes = ms.ToArray(); + } + finally + { + BodyReadBytes = ms.Length; + BodyReadDurationMilliseconds = Stopwatch.GetElapsedTime(bodyReadStart).TotalMilliseconds; + } } return BodyBytes; diff --git a/src/SimpleL7Proxy/SimpleL7Proxy.csproj b/src/SimpleL7Proxy/SimpleL7Proxy.csproj index eb020dd3..9e77a726 100644 --- a/src/SimpleL7Proxy/SimpleL7Proxy.csproj +++ b/src/SimpleL7Proxy/SimpleL7Proxy.csproj @@ -2,7 +2,7 @@ Exe - net10.0 + net9.0 enable enable Debug;Release;test diff --git a/src/SimpleL7Proxy/build.sh b/src/SimpleL7Proxy/build.sh old mode 100644 new mode 100755