Merge pull request #30796 from dgoodwin/graceful-term-time

NO-JIRA: Fix lack of human readable timestamps in two tests output

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

test/extended/machines/cluster.go

@@ -244,8 +244,8 @@ func (a byTime) Less(i, j int) bool {
 	return a[i].time.Before(a[j].time)
 }
 
-func (e *bootTimelineEntry) String() string {
-	return fmt.Sprintf("%v - %v", e.time.String(), e.action)
+func (e bootTimelineEntry) String() string {
+	return fmt.Sprintf("%v - %v", e.time.Format(time.RFC3339), e.action)
 }
 
 func parseBootInstances(listBootsOutput string) ([]bootTimelineEntry, error) {

test/extended/machines/cluster_test.go

@@ -1,6 +1,7 @@
 package operators
 
 import (
+	"fmt"
 	"reflect"
 	"testing"
 	"time"
@@ -52,6 +53,53 @@ func Test_parseBootInstances(t *testing.T) {
 	}
 }
 
+func Test_bootTimelineEntryString(t *testing.T) {
+	tests := []struct {
+		name     string
+		entry    bootTimelineEntry
+		expected string
+	}{
+		{
+			name:     "boot entry formats time as RFC3339",
+			entry:    bootTimelineEntry{action: "Boot", time: mustTime("2026-01-20T22:20:50Z")},
+			expected: "2026-01-20T22:20:50Z - Boot",
+		},
+		{
+			name:     "reboot request entry formats time as RFC3339",
+			entry:    bootTimelineEntry{action: "RebootRequest", time: mustTime("2024-03-13T10:20:01-04:00")},
+			expected: "2024-03-13T10:20:01-04:00 - RebootRequest",
+		},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			result := tt.entry.String()
+			if result != tt.expected {
+				t.Errorf("String() = %q, want %q", result, tt.expected)
+			}
+		})
+	}
+}
+
+func Test_bootTimelineSliceFormat(t *testing.T) {
+	// Verify that formatting a []bootTimelineEntry with %v calls String() on each element,
+	// producing human-readable timestamps instead of raw struct output.
+	entries := []bootTimelineEntry{
+		{action: "Boot", time: mustTime("2026-01-20T22:20:50Z")},
+		{action: "RebootRequest", time: mustTime("2026-01-20T22:01:27Z")},
+	}
+	formatted := fmt.Sprintf("%v", entries)
+	if formatted == fmt.Sprintf("%v", []struct {
+		action string
+		time   time.Time
+	}{{action: "Boot"}, {action: "RebootRequest"}}) {
+		t.Error("slice formatting is not using String() method")
+	}
+	expected := "[2026-01-20T22:20:50Z - Boot 2026-01-20T22:01:27Z - RebootRequest]"
+	if formatted != expected {
+		t.Errorf("formatted slice = %q, want %q", formatted, expected)
+	}
+}
+
 func Test_parseRebootInstances(t *testing.T) {
 	type args struct {
 		rebootsOutput string