Bugfix/tokenrefresh

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

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"]}

src/Shared-parser/Shared-parser.csproj

@@ -1,6 +1,6 @@
 <Project Sdk="Microsoft.NET.Sdk">
   <PropertyGroup>
-    <TargetFramework>net10.0</TargetFramework>
+    <TargetFramework>net9.0</TargetFramework>
     <ImplicitUsings>enable</ImplicitUsings>
     <Nullable>enable</Nullable>
   </PropertyGroup>

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/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<string, AccessToken> _tokenDict = new();
-        private readonly Dictionary<string, DateTimeOffset> _tokenExpiryDict = new();
+        private readonly ConcurrentDictionary<string, AccessToken> _tokenDict = new();
         private readonly HashSet<string> _audiences = new();
         private readonly Dictionary<string, Task> _refreshTasks = new();
         private static CancellationToken _cancellationToken = CancellationToken.None;
@@ -60,15 +62,17 @@ public async Task<string> 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
                         }
                     }
                 }

src/SimpleL7Proxy/Backend/HostConfig.cs

@@ -185,8 +185,13 @@ public static void Initialize(BackendTokenProvider tokenProvider, ILogger logger
     /// </summary>
     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 = "")
     /// <summary>
     /// Parses a backend configuration string into a ParsedConfig struct.
     /// </summary>
@@ -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

src/SimpleL7Proxy/Config/ProxyConfig.cs

@@ -64,7 +64,7 @@ public class ProxyConfig
     [ConfigOption("Logging:LogToConsole")]
     public List<string> LogToConsole { get; set; } = ["*", "-custom"];
     [ConfigOption("Logging:LogToEvents")]
-    public List<string> LogToEvents { get; set; } = ["async","backend","probe","circuitbreaker","custom","exception","profile","proxy","enqueued","auth"];
+    public List<string> LogToEvents { get; set; } = ["async","exception","backend","probe","circuitbreaker","custom","exception","profile","proxy","enqueued","auth"];
 
     // ── Profiles ──
     [ConfigOption("Profiles:Auth:ConfigUrl")]

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;
 

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