fix(usage): reset first-byte latency per upstream attempt

Track first-byte timestamps per upstream attempt so retries do not reuse stale response times and drop successful latency metrics.

Author: NGLSL

internal/runtime/executor/helps/logging_helpers.go

@@ -20,10 +20,11 @@ import (
 )
 
 const (
-	apiAttemptsKey          = "API_UPSTREAM_ATTEMPTS"
-	apiRequestKey           = "API_REQUEST"
-	apiResponseKey          = "API_RESPONSE"
-	apiWebsocketTimelineKey = "API_WEBSOCKET_TIMELINE"
+	apiAttemptsKey                 = "API_UPSTREAM_ATTEMPTS"
+	apiRequestKey                  = "API_REQUEST"
+	apiResponseKey                 = "API_RESPONSE"
+	apiWebsocketTimelineKey        = "API_WEBSOCKET_TIMELINE"
+	apiAttemptResponseTimestampKey = "API_ATTEMPT_RESPONSE_TIMESTAMP"
 )
 
 // UpstreamRequestLog captures the outbound upstream request details for logging.
@@ -54,10 +55,13 @@ type upstreamAttempt struct {
 
 // RecordAPIRequest stores the upstream request metadata in Gin context for request logging.
 func RecordAPIRequest(ctx context.Context, cfg *config.Config, info UpstreamRequestLog) {
+	ginCtx := ginContextFrom(ctx)
+	if ginCtx != nil {
+		ginCtx.Set(apiAttemptResponseTimestampKey, time.Time{})
+	}
 	if cfg == nil || !cfg.RequestLog {
 		return
 	}
-	ginCtx := ginContextFrom(ctx)
 	if ginCtx == nil {
 		return
 	}
@@ -206,10 +210,13 @@ func AppendAPIResponseChunk(ctx context.Context, cfg *config.Config, chunk []byt
 
 // RecordAPIWebsocketRequest stores an upstream websocket request event in Gin context.
 func RecordAPIWebsocketRequest(ctx context.Context, cfg *config.Config, info UpstreamRequestLog) {
+	ginCtx := ginContextFrom(ctx)
+	if ginCtx != nil {
+		ginCtx.Set(apiAttemptResponseTimestampKey, time.Time{})
+	}
 	if cfg == nil || !cfg.RequestLog {
 		return
 	}
-	ginCtx := ginContextFrom(ctx)
 	if ginCtx == nil {
 		return
 	}
@@ -451,10 +458,16 @@ func markAPIResponseTimestamp(ginCtx *gin.Context) {
 	if ginCtx == nil {
 		return
 	}
+	now := time.Now()
+	if value, exists := ginCtx.Get(apiAttemptResponseTimestampKey); !exists {
+		ginCtx.Set(apiAttemptResponseTimestampKey, now)
+	} else if timestamp, ok := value.(time.Time); !ok || timestamp.IsZero() {
+		ginCtx.Set(apiAttemptResponseTimestampKey, now)
+	}
 	if _, exists := ginCtx.Get("API_RESPONSE_TIMESTAMP"); exists {
 		return
 	}
-	ginCtx.Set("API_RESPONSE_TIMESTAMP", time.Now())
+	ginCtx.Set("API_RESPONSE_TIMESTAMP", now)
 }
 
 func writeHeaders(builder *strings.Builder, headers http.Header) {

internal/runtime/executor/helps/usage_helpers.go

@@ -140,6 +140,13 @@ func apiResponseTimestampFromContext(ctx context.Context) time.Time {
 	if !ok || ginCtx == nil {
 		return time.Time{}
 	}
+	if value, exists := ginCtx.Get(apiAttemptResponseTimestampKey); exists {
+		timestamp, ok := value.(time.Time)
+		if !ok {
+			return time.Time{}
+		}
+		return timestamp
+	}
 	value, exists := ginCtx.Get("API_RESPONSE_TIMESTAMP")
 	if !exists {
 		return time.Time{}

internal/runtime/executor/helps/usage_helpers_test.go

@@ -90,3 +90,50 @@ func TestUsageReporterBuildRecordIncludesFirstByteLatency(t *testing.T) {
 		t.Fatalf("first byte latency = %v, want 250ms", record.FirstByteLatency)
 	}
 }
+
+func TestUsageReporterBuildRecordPrefersAttemptFirstByteLatency(t *testing.T) {
+	gin.SetMode(gin.TestMode)
+
+	recorder := httptest.NewRecorder()
+	ginCtx, _ := gin.CreateTestContext(recorder)
+	requestedAt := time.Now().Add(-1500 * time.Millisecond)
+	staleFirstByteAt := requestedAt.Add(-200 * time.Millisecond)
+	attemptFirstByteAt := requestedAt.Add(250 * time.Millisecond)
+	ginCtx.Set("API_RESPONSE_TIMESTAMP", staleFirstByteAt)
+	ginCtx.Set(apiAttemptResponseTimestampKey, attemptFirstByteAt)
+
+	ctx := context.WithValue(context.Background(), "gin", ginCtx)
+	reporter := &UsageReporter{
+		provider:    "openai",
+		model:       "gpt-5.4",
+		requestedAt: requestedAt,
+	}
+
+	record := reporter.buildRecord(ctx, usage.Detail{TotalTokens: 3}, false)
+	if record.FirstByteLatency != 250*time.Millisecond {
+		t.Fatalf("first byte latency = %v, want 250ms", record.FirstByteLatency)
+	}
+}
+
+func TestUsageReporterBuildRecordDoesNotFallbackToGlobalTimestampAfterAttemptReset(t *testing.T) {
+	gin.SetMode(gin.TestMode)
+
+	recorder := httptest.NewRecorder()
+	ginCtx, _ := gin.CreateTestContext(recorder)
+	requestedAt := time.Now().Add(-1500 * time.Millisecond)
+	staleFirstByteAt := requestedAt.Add(-200 * time.Millisecond)
+	ginCtx.Set("API_RESPONSE_TIMESTAMP", staleFirstByteAt)
+	ginCtx.Set(apiAttemptResponseTimestampKey, time.Time{})
+
+	ctx := context.WithValue(context.Background(), "gin", ginCtx)
+	reporter := &UsageReporter{
+		provider:    "openai",
+		model:       "gpt-5.4",
+		requestedAt: requestedAt,
+	}
+
+	record := reporter.buildRecord(ctx, usage.Detail{TotalTokens: 3}, false)
+	if record.FirstByteLatency != 0 {
+		t.Fatalf("first byte latency = %v, want 0", record.FirstByteLatency)
+	}
+}