action: include TS in LogBuffer

This provides more context to individual log entries (and the duration
between individual log lines) while e.g. printing them in an event.

Signed-off-by: Hidde Beydals <hello@hidde.co>

internal/action/log.go

@@ -21,6 +21,7 @@ import (
 	"fmt"
 	"strings"
 	"sync"
+	"time"
 
 	"github.com/go-logr/logr"
 	helmaction "helm.sh/helm/v3/pkg/action"
@@ -29,6 +30,9 @@ import (
 // DefaultLogBufferSize is the default size of the LogBuffer.
 const DefaultLogBufferSize = 5
 
+// nowTS can be used to stub out time.Now() in tests.
+var nowTS = time.Now
+
 // NewDebugLog returns an action.DebugLog that logs to the given logr.Logger.
 func NewDebugLog(log logr.Logger) helmaction.DebugLog {
 	return func(format string, v ...interface{}) {
@@ -43,6 +47,35 @@ type LogBuffer struct {
 	buffer *ring.Ring
 }
 
+// logLine is a log message with a timestamp.
+type logLine struct {
+	ts     time.Time
+	lastTS time.Time
+	msg    string
+	count  int64
+}
+
+// String returns the log line as a string, in the format of:
+// '<RFC3339 nano timestamp>: <message>'. But only if the message is not empty.
+func (l *logLine) String() string {
+	if l == nil || l.msg == "" {
+		return ""
+	}
+
+	msg := fmt.Sprintf("%s %s", l.ts.Format(time.RFC3339Nano), l.msg)
+	if c := l.count; c > 0 {
+		msg += fmt.Sprintf("\n%s %s", l.lastTS.Format(time.RFC3339Nano), l.msg)
+	}
+	if c := l.count - 1; c > 0 {
+		var dup = "line"
+		if c > 1 {
+			dup += "s"
+		}
+		msg += fmt.Sprintf(" (%d duplicate %s omitted)", c, dup)
+	}
+	return msg
+}
+
 // NewLogBuffer creates a new LogBuffer with the given log function
 // and a buffer of the given size. If size <= 0, it defaults to
 // DefaultLogBufferSize.
@@ -64,8 +97,17 @@ func (l *LogBuffer) Log(format string, v ...interface{}) {
 	// Filter out duplicate log lines, this happens for example when
 	// Helm is waiting on workloads to become ready.
 	msg := fmt.Sprintf(format, v...)
-	if prev := l.buffer.Prev(); prev.Value != msg {
-		l.buffer.Value = msg
+	prev, ok := l.buffer.Prev().Value.(*logLine)
+	if ok && prev.msg == msg {
+		prev.count++
+		prev.lastTS = nowTS().UTC()
+		l.buffer.Prev().Value = prev
+	}
+	if !ok || prev.msg != msg {
+		l.buffer.Value = &logLine{
+			ts:  nowTS().UTC(),
+			msg: msg,
+		}
 		l.buffer = l.buffer.Next()
 	}
 
@@ -74,19 +116,20 @@ func (l *LogBuffer) Log(format string, v ...interface{}) {
 }
 
 // Len returns the count of non-empty values in the buffer.
-func (l *LogBuffer) Len() int {
-	var count int
+func (l *LogBuffer) Len() (count int) {
 	l.mu.RLock()
 	l.buffer.Do(func(s interface{}) {
 		if s == nil {
 			return
 		}
-		if s.(string) != "" {
-			count++
+		ll, ok := s.(*logLine)
+		if !ok || ll.String() == "" {
+			return
 		}
+		count++
 	})
 	l.mu.RUnlock()
-	return count
+	return
 }
 
 // Reset clears the buffer.
@@ -104,7 +147,13 @@ func (l *LogBuffer) String() string {
 		if s == nil {
 			return
 		}
-		str += s.(string) + "\n"
+		ll, ok := s.(*logLine)
+		if !ok {
+			return
+		}
+		if msg := ll.String(); msg != "" {
+			str += msg + "\n"
+		}
 	})
 	l.mu.RUnlock()
 	return strings.TrimSpace(str)

internal/action/log_test.go

@@ -17,12 +17,16 @@ limitations under the License.
 package action
 
 import (
+	"fmt"
 	"testing"
+	"time"
 
 	"github.com/go-logr/logr"
 )
 
 func TestLogBuffer_Log(t *testing.T) {
+	nowTS = stubNowTS
+
 	tests := []struct {
 		name      string
 		size      int
@@ -30,7 +34,7 @@ func TestLogBuffer_Log(t *testing.T) {
 		wantCount int
 		want      string
 	}{
-		{name: "log", size: 2, fill: []string{"a", "b", "c"}, wantCount: 3, want: "b\nc"},
+		{name: "log", size: 2, fill: []string{"a", "b", "c"}, wantCount: 3, want: fmt.Sprintf("%[1]s b\n%[1]s c", stubNowTS().Format(time.RFC3339Nano))},
 	}
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
@@ -102,6 +106,8 @@ func TestLogBuffer_Reset(t *testing.T) {
 }
 
 func TestLogBuffer_String(t *testing.T) {
+	nowTS = stubNowTS
+
 	tests := []struct {
 		name string
 		size int
@@ -109,8 +115,11 @@ func TestLogBuffer_String(t *testing.T) {
 		want string
 	}{
 		{name: "empty buffer", fill: []string{}, want: ""},
-		{name: "filled buffer", size: 2, fill: []string{"a", "b", "c"}, want: "b\nc"},
-		{name: "duplicate buffer items", fill: []string{"b", "b", "b"}, want: "b"},
+		{name: "filled buffer", size: 2, fill: []string{"a", "b", "c"}, want: fmt.Sprintf("%[1]s b\n%[1]s c", stubNowTS().Format(time.RFC3339Nano))},
+		{name: "duplicate buffer items", fill: []string{"b", "b"}, want: fmt.Sprintf("%[1]s b\n%[1]s b", stubNowTS().Format(time.RFC3339Nano))},
+		{name: "duplicate buffer items", fill: []string{"b", "b", "b"}, want: fmt.Sprintf("%[1]s b\n%[1]s b (1 duplicate line omitted)", stubNowTS().Format(time.RFC3339Nano))},
+		{name: "duplicate buffer items", fill: []string{"b", "b", "b", "b"}, want: fmt.Sprintf("%[1]s b\n%[1]s b (2 duplicate lines omitted)", stubNowTS().Format(time.RFC3339Nano))},
+		{name: "duplicate buffer items", fill: []string{"a", "b", "b", "b", "c", "c"}, want: fmt.Sprintf("%[1]s a\n%[1]s b\n%[1]s b (1 duplicate line omitted)\n%[1]s c\n%[1]s c", stubNowTS().Format(time.RFC3339Nano))},
 	}
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
@@ -124,3 +133,8 @@ func TestLogBuffer_String(t *testing.T) {
 		})
 	}
 }
+
+// stubNowTS returns a fixed time for testing purposes.
+func stubNowTS() time.Time {
+	return time.Date(2016, 2, 18, 12, 24, 5, 12345600, time.UTC)
+}