Fix latency for stream req

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

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)

src/Shared-parser/StreamProcessor/MultiAllUsageProcessor.cs

@@ -16,7 +16,7 @@ public class MultiLineAllUsageProcessor : JsonStreamProcessor
             @"""(?:[uU]sage|[uU]sage[mM]etadata)"":\s*(\{(?:[^{}]|(?<open>\{)|(?<-open>\}))*(?(open)(?!))\})",
             RegexOptions.Singleline | RegexOptions.Compiled);
 
-        protected override int MaxLines => 100;
+        protected override int MaxLines => 50;
         protected override int MinLineLength => 1;
 
         /// <summary>

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;
 

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
 
     /// <summary>
     /// 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.
     /// </summary>
     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);
     }
+
+    /// <summary>
+    /// 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.
+    /// </summary>
+    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);
+    }
 }

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