From 80c3d91f44bbd86b5eef9bb23959d3af84125c2c Mon Sep 17 00:00:00 2001
From: Chao Chen <chaochn@amazon.com>
Date: Tue, 9 Dec 2025 21:17:32 +0000
Subject: [PATCH] Bugfix: calculate request latency properly in audit log
 filter

Signed-off-by: Chao Chen <chaochn@amazon.com>
---
 .../apiserver/pkg/endpoints/filters/audit.go  |  3 +--
 .../pkg/endpoints/filters/audit_test.go       | 21 ++++++++++++++++++-
 2 files changed, 21 insertions(+), 3 deletions(-)

diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit.go b/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit.go
index d25bf35ae3a..83537bd215e 100644
--- a/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit.go
+++ b/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit.go
@@ -149,7 +149,6 @@ func evaluatePolicyAndCreateAuditEvent(req *http.Request, policy audit.PolicyRul
 
 // writeLatencyToAnnotation writes the latency incurred in different
 // layers of the apiserver to the annotations of the audit object.
-// it should be invoked after ev.StageTimestamp has been set appropriately.
 func writeLatencyToAnnotation(ctx context.Context) {
 	ac := audit.AuditContextFrom(ctx)
 	// we will track latency in annotation only when the total latency
@@ -157,7 +156,7 @@ func writeLatencyToAnnotation(ctx context.Context) {
 	// traces in rest/handlers for create, delete, update,
 	// get, list, and deletecollection.
 	const threshold = 500 * time.Millisecond
-	latency := ac.GetEventStageTimestamp().Sub(ac.GetEventRequestReceivedTimestamp().Time)
+	latency := time.Since(ac.GetEventRequestReceivedTimestamp().Time)
 	if latency <= threshold {
 		return
 	}
diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit_test.go b/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit_test.go
index e2e77ac3742..03bac7a07b3 100644
--- a/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit_test.go
+++ b/staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit_test.go
@@ -23,6 +23,7 @@ import (
 	"net/http/httptest"
 	"net/url"
 	"reflect"
+	"regexp"
 	"sync"
 	"testing"
 	"time"
@@ -224,7 +225,7 @@ func TestAudit(t *testing.T) {
 	shortRunningPath := "/api/v1/namespaces/default/pods/foo"
 	longRunningPath := "/api/v1/namespaces/default/pods?watch=true"
 
-	delay := 500 * time.Millisecond
+	delay := 501 * time.Millisecond
 
 	for _, test := range []struct {
 		desc       string
@@ -351,6 +352,10 @@ func TestAudit(t *testing.T) {
 					Verb:           "update",
 					RequestURI:     shortRunningPath,
 					ResponseStatus: &metav1.Status{Code: 200},
+					Annotations: map[string]string{
+						"apiserver.latency.k8s.io/response-write": "^[0-9.]+[µnm]s$",
+						"apiserver.latency.k8s.io/total":          "^[0-9.]+[µnm]s$",
+					},
 				},
 			},
 			true,
@@ -713,6 +718,7 @@ func TestAudit(t *testing.T) {
 				// simplified long-running check
 				return ri.Verb == "watch"
 			})
+			handler = WithLatencyTrackers(handler)
 			handler = WithAuditInit(handler)
 
 			req, _ := http.NewRequestWithContext(ctx, test.verb, test.path, nil)
@@ -772,6 +778,19 @@ func TestAudit(t *testing.T) {
 				if (event.ResponseStatus != nil) && (event.ResponseStatus.Code != expect.ResponseStatus.Code) {
 					t.Errorf("Unexpected status code : %d", event.ResponseStatus.Code)
 				}
+
+				for k, v := range expect.Annotations {
+					if actual, exists := event.Annotations[k]; !exists {
+						t.Errorf("Expect key %s in the annotations but it does not exist", k)
+					} else if matched, _ := regexp.MatchString(v, actual); !matched {
+						t.Errorf("Annotation %s value %q does not match regex %q", k, actual, v)
+					}
+				}
+				for k := range event.Annotations {
+					if _, exists := expect.Annotations[k]; !exists {
+						t.Errorf("Unexpected key %s in the annotations", k)
+					}
+				}
 			}
 		})
 	}