diff --git a/ReleaseNotes/version2.2.md b/ReleaseNotes/version2.2.md index 0789c82b..2ddc3133 100644 --- a/ReleaseNotes/version2.2.md +++ b/ReleaseNotes/version2.2.md @@ -1,6 +1,7 @@ # Release Notes # 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/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/Constants.cs b/src/SimpleL7Proxy/Constants.cs index f639131b..311153ec 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"; 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..dfd44d69 100644 --- a/src/SimpleL7Proxy/Proxy/ProxyWorker.cs +++ b/src/SimpleL7Proxy/Proxy/ProxyWorker.cs @@ -555,6 +555,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