Report observed time when kubelet logs failed graceful termination

This should allow better insight into when to look for problems in intervals than the pod start time.

Author: dgoodwin

test/extended/apiserver/graceful_termination.go

@@ -7,6 +7,7 @@ import (
 	"fmt"
 	"regexp"
 	"strings"
+	"time"
 
 	g "github.com/onsi/ginkgo/v2"
 	o "github.com/onsi/gomega"
@@ -60,6 +61,8 @@ var _ = g.Describe("[sig-api-machinery][Feature:APIServer][Late]", func() {
 	g.It("kubelet terminates kube-apiserver gracefully extended", func() {
 		var finalMessageBuilder strings.Builder
 		terminationRegexp := regexp.MustCompile(`Previous pod .* did not terminate gracefully`)
+		// klog timestamp format: W0120 22:20:50.473381
+		klogTimestampRegexp := regexp.MustCompile(`^[IWEF](\d{4}) (\d{2}:\d{2}:\d{2}\.\d+)`)
 
 		masters, err := oc.AsAdmin().KubeClient().CoreV1().Nodes().List(context.Background(), metav1.ListOptions{LabelSelector: "node-role.kubernetes.io/master"})
 		o.Expect(err).NotTo(o.HaveOccurred())
@@ -79,7 +82,8 @@ var _ = g.Describe("[sig-api-machinery][Feature:APIServer][Late]", func() {
 				for kasTerminationFileScanner.Scan() {
 					line := kasTerminationFileScanner.Text()
 					if terminationRegexp.MatchString(line) {
-						finalMessageBuilder.WriteString(fmt.Sprintf("\n kube-apiserver on node %s wasn't gracefully terminated, reason: %s", master.Name, line))
+						observedAt := parseKlogTimestamp(line, klogTimestampRegexp)
+						finalMessageBuilder.WriteString(fmt.Sprintf("\n kube-apiserver on node %s wasn't gracefully terminated (observed at %s), reason: %s", master.Name, observedAt, line))
 					}
 				}
 				o.Expect(kasTerminationFileScanner.Err()).NotTo(o.HaveOccurred())
@@ -185,3 +189,20 @@ func extractAPIServerNameFromAuditFile(auditFileName string) string {
 func isKASTerminationLogFile(fileName string) bool {
 	return strings.Contains(fileName, "termination")
 }
+
+// parseKlogTimestamp extracts and formats the klog timestamp from a log line.
+// klog timestamps have the format: W0120 22:20:50.473381 (MMDD HH:MM:SS.ffffff without year).
+// We use the current year as klog does not include it.
+func parseKlogTimestamp(line string, klogTimestampRegexp *regexp.Regexp) string {
+	matches := klogTimestampRegexp.FindStringSubmatch(line)
+	if len(matches) < 3 {
+		return "unknown"
+	}
+	// matches[1] = "0120" (MMDD), matches[2] = "22:20:50.473381"
+	timestampStr := fmt.Sprintf("%d-%s-%s", time.Now().Year(), matches[1][:2]+"-"+matches[1][2:], matches[2])
+	t, err := time.Parse("2006-01-02-15:04:05.000000", timestampStr)
+	if err != nil {
+		return matches[1] + " " + matches[2]
+	}
+	return t.Format(time.RFC3339)
+}

test/extended/apiserver/graceful_termination_test.go

@@ -0,0 +1,54 @@
+package apiserver
+
+import (
+	"fmt"
+	"regexp"
+	"testing"
+	"time"
+)
+
+func TestParseKlogTimestamp(t *testing.T) {
+	klogTimestampRegexp := regexp.MustCompile(`^[IWEF](\d{4}) (\d{2}:\d{2}:\d{2}\.\d+)`)
+	currentYear := time.Now().Year()
+
+	tests := []struct {
+		name     string
+		line     string
+		expected string
+	}{
+		{
+			name:     "warning log line with graceful termination message",
+			line:     `W0120 22:20:50.473381       1 main.go:136] Previous pod kube-apiserver-ip-10-0-48-191.us-west-2.compute.internal started at 2026-01-20 22:01:27.176604246 +0000 UTC did not terminate gracefully`,
+			expected: fmt.Sprintf("%d-01-20T22:20:50Z", currentYear),
+		},
+		{
+			name:     "info level log line",
+			line:     `I0315 10:05:30.123456       1 main.go:100] some info message`,
+			expected: fmt.Sprintf("%d-03-15T10:05:30Z", currentYear),
+		},
+		{
+			name:     "error level log line",
+			line:     `E1231 23:59:59.999999       1 main.go:200] error message`,
+			expected: fmt.Sprintf("%d-12-31T23:59:59Z", currentYear),
+		},
+		{
+			name:     "no klog prefix",
+			line:     `some random log line without a timestamp`,
+			expected: "unknown",
+		},
+		{
+			name:     "empty line",
+			line:     ``,
+			expected: "unknown",
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			result := parseKlogTimestamp(tt.line, klogTimestampRegexp)
+			if result != tt.expected {
+				t.Errorf("parseKlogTimestamp() = %q, want %q", result, tt.expected)
+			}
+		})
+	}
+}