Merge pull request #91207 from iamchuckss/fixed-width-log-timestamps

Fix log timestamps to maintain a fixed width

pkg/apis/core/types.go

@@ -4252,7 +4252,7 @@ type PodLogOptions struct {
 	// If this value is in the future, no logs will be returned.
 	// Only one of sinceSeconds or sinceTime may be specified.
 	SinceTime *metav1.Time
-	// If true, add an RFC3339 or RFC3339Nano timestamp at the beginning of every line
+	// If true, add an RFC 3339 timestamp with 9 digits of fractional seconds at the beginning of every line
 	// of log output.
 	Timestamps bool
 	// If set, the number of lines from the end of the logs to show. If not specified,

pkg/kubelet/kuberuntime/logs/BUILD

@@ -6,6 +6,7 @@ go_library(
     importpath = "k8s.io/kubernetes/pkg/kubelet/kuberuntime/logs",
     visibility = ["//visibility:public"],
     deps = [
+        "//pkg/kubelet/types:go_default_library",
         "//pkg/util/tail:go_default_library",
         "//staging/src/k8s.io/api/core/v1:go_default_library",
         "//staging/src/k8s.io/cri-api/pkg/apis:go_default_library",

pkg/kubelet/kuberuntime/logs/logs.go

@@ -35,6 +35,7 @@ import (
 	"k8s.io/api/core/v1"
 	internalapi "k8s.io/cri-api/pkg/apis"
 	runtimeapi "k8s.io/cri-api/pkg/apis/runtime/v1alpha2"
+	"k8s.io/kubernetes/pkg/kubelet/types"
 	"k8s.io/kubernetes/pkg/util/tail"
 )
 
@@ -47,8 +48,10 @@ import (
 // TODO(random-liu): Support log rotation.
 
 const (
-	// timeFormat is the time format used in the log.
+	// timeFormatOut is the format for writing timestamps to output.
-	timeFormat = time.RFC3339Nano
+	timeFormatOut = types.RFC3339NanoFixed
+	// timeFormatIn is the format for parsing timestamps from other logs.
+	timeFormatIn = types.RFC3339NanoLenient
 
 	// logForceCheckPeriod is the period to check for a new read
 	logForceCheckPeriod = 1 * time.Second
@@ -128,9 +131,9 @@ func parseCRILog(log []byte, msg *logMessage) error {
 	if idx < 0 {
 		return fmt.Errorf("timestamp is not found")
 	}
-	msg.timestamp, err = time.Parse(timeFormat, string(log[:idx]))
+	msg.timestamp, err = time.Parse(timeFormatIn, string(log[:idx]))
 	if err != nil {
-		return fmt.Errorf("unexpected timestamp format %q: %v", timeFormat, err)
+		return fmt.Errorf("unexpected timestamp format %q: %v", timeFormatIn, err)
 	}
 
 	// Parse stream type
@@ -238,7 +241,7 @@ func (w *logWriter) write(msg *logMessage) error {
 	}
 	line := msg.log
 	if w.opts.timestamp {
-		prefix := append([]byte(msg.timestamp.Format(timeFormat)), delimiter[0])
+		prefix := append([]byte(msg.timestamp.Format(timeFormatOut)), delimiter[0])
 		line = append(prefix, line...)
 	}
 	// If the line is longer than the remaining bytes, cut it.

pkg/kubelet/kuberuntime/logs/logs_test.go

@@ -67,7 +67,7 @@ func TestLogOptions(t *testing.T) {
 }
 
 func TestParseLog(t *testing.T) {
-	timestamp, err := time.Parse(timeFormat, "2016-10-20T18:39:20.57606443Z")
+	timestamp, err := time.Parse(timeFormatIn, "2016-10-20T18:39:20.57606443Z")
 	assert.NoError(t, err)
 	msg := &logMessage{}
 	for c, test := range []struct {
@@ -143,7 +143,7 @@ func TestParseLog(t *testing.T) {
 }
 
 func TestWriteLogs(t *testing.T) {
-	timestamp := time.Unix(1234, 4321)
+	timestamp := time.Unix(1234, 43210)
 	log := "abcdefg\n"
 
 	for c, test := range []struct {
@@ -168,7 +168,7 @@ func TestWriteLogs(t *testing.T) {
 		{ // timestamp enabled
 			stream:       runtimeapi.Stderr,
 			timestamp:    true,
-			expectStderr: timestamp.Format(timeFormat) + " " + log,
+			expectStderr: timestamp.Format(timeFormatOut) + " " + log,
 		},
 	} {
 		t.Logf("TestCase #%d: %+v", c, test)
@@ -189,7 +189,7 @@ func TestWriteLogs(t *testing.T) {
 
 func TestWriteLogsWithBytesLimit(t *testing.T) {
 	timestamp := time.Unix(1234, 4321)
-	timestampStr := timestamp.Format(timeFormat)
+	timestampStr := timestamp.Format(timeFormatOut)
 	log := "abcdefg\n"
 
 	for c, test := range []struct {

pkg/kubelet/types/constants.go

@@ -29,4 +29,9 @@ const (
 	SystemReservedEnforcementKey  = "system-reserved"
 	KubeReservedEnforcementKey    = "kube-reserved"
 	NodeAllocatableNoneKey        = "none"
+
+	// fixed width version of time.RFC3339Nano
+	RFC3339NanoFixed = "2006-01-02T15:04:05.000000000Z07:00"
+	// variable width RFC3339 time format for lenient parsing of strings into timestamps
+	RFC3339NanoLenient = "2006-01-02T15:04:05.999999999Z07:00"
 )

pkg/kubelet/types/types.go

@@ -43,10 +43,10 @@ func NewTimestamp() *Timestamp {
 	return &Timestamp{time.Now()}
 }
 
-// ConvertToTimestamp takes a string, parses it using the RFC3339Nano layout,
+// ConvertToTimestamp takes a string, parses it using the RFC3339NanoLenient layout,
 // and converts it to a Timestamp object.
 func ConvertToTimestamp(timeString string) *Timestamp {
-	parsed, _ := time.Parse(time.RFC3339Nano, timeString)
+	parsed, _ := time.Parse(RFC3339NanoLenient, timeString)
 	return &Timestamp{parsed}
 }
 
@@ -55,10 +55,10 @@ func (t *Timestamp) Get() time.Time {
 	return t.time
 }
 
-// GetString returns the time in the string format using the RFC3339Nano
+// GetString returns the time in the string format using the RFC3339NanoFixed
 // layout.
 func (t *Timestamp) GetString() string {
-	return t.time.Format(time.RFC3339Nano)
+	return t.time.Format(RFC3339NanoFixed)
 }
 
 // A type to help sort container statuses based on container names.