Add timestamp to console logs (#4344)

It looks like we dropped this out of the zap logs, way back in
#69. @emcfarlane correctly ported the lack of a timestamp
over to slog in #3844. This probably made sense when `buf` was running
fairly quick CLI commands, but now that we have various server processes
running from `buf`, it makes sense to add a timestamp for the various
logs being emitted. I specifically wanted this when debugging `buf lsp
serve`.

We _could_ just make this optional (only for certain commands), but this
feels fairly uncontroversial.

Author: stefanvanburen

private/bufpkg/bufconnect/interceptors_test.go

@@ -19,8 +19,9 @@ import (
 	"context"
 	"encoding/base64"
 	"errors"
-	"fmt"
+	"strings"
 	"testing"
+	"time"
 
 	"buf.build/go/app"
 	"buf.build/go/app/appext"
@@ -54,7 +55,7 @@ func TestNewAuthorizationInterceptorProvider(t *testing.T) {
 			return nil, errors.New("error auth token")
 		}
 		return nil, nil
-	})(context.Background(), connect.NewRequest(&bytes.Buffer{}))
+	})(t.Context(), connect.NewRequest(&bytes.Buffer{}))
 	assert.NoError(t, err)
 
 	getMachineForName := func(app.EnvContainer, string) (netrc.Machine, error) {
@@ -67,7 +68,7 @@ func TestNewAuthorizationInterceptorProvider(t *testing.T) {
 			return nil, errors.New("error auth token")
 		}
 		return nil, nil
-	})(context.Background(), connect.NewRequest(&bytes.Buffer{}))
+	})(t.Context(), connect.NewRequest(&bytes.Buffer{}))
 	assert.NoError(t, err)
 
 	// testing using tokenSet over netrc tokenToAuthKey
@@ -76,7 +77,7 @@ func TestNewAuthorizationInterceptorProvider(t *testing.T) {
 			return nil, errors.New("error auth token")
 		}
 		return nil, nil
-	})(context.Background(), connect.NewRequest(&bytes.Buffer{}))
+	})(t.Context(), connect.NewRequest(&bytes.Buffer{}))
 	assert.NoError(t, err)
 
 	// testing using netrc tokenToAuthKey over tokenSet
@@ -85,15 +86,15 @@ func TestNewAuthorizationInterceptorProvider(t *testing.T) {
 			return nil, errors.New("error auth token")
 		}
 		return nil, nil
-	})(context.Background(), connect.NewRequest(&bytes.Buffer{}))
+	})(t.Context(), connect.NewRequest(&bytes.Buffer{}))
 	assert.NoError(t, err)
 
 	_, err = NewAuthorizationInterceptorProvider()("default")(func(ctx context.Context, req connect.AnyRequest) (connect.AnyResponse, error) {
 		if req.Header().Get(AuthenticationHeader) != "" {
 			return nil, errors.New("error auth token")
 		}
 		return nil, nil
-	})(context.Background(), connect.NewRequest(&bytes.Buffer{}))
+	})(t.Context(), connect.NewRequest(&bytes.Buffer{}))
 	assert.NoError(t, err)
 
 	tokenSet, err = NewTokenProviderFromContainer(app.NewEnvContainer(map[string]string{
@@ -102,7 +103,7 @@ func TestNewAuthorizationInterceptorProvider(t *testing.T) {
 	assert.NoError(t, err)
 	_, err = NewAuthorizationInterceptorProvider(tokenSet)("default")(func(ctx context.Context, req connect.AnyRequest) (connect.AnyResponse, error) {
 		return nil, errors.New("underlying cause")
-	})(context.Background(), connect.NewRequest(&bytes.Buffer{}))
+	})(t.Context(), connect.NewRequest(&bytes.Buffer{}))
 	authErr, ok := AsAuthError(err)
 	assert.True(t, ok)
 	assert.Equal(t, TokenEnvKey, authErr.tokenEnvKey)
@@ -119,15 +120,15 @@ func TestCLIWarningInterceptor(t *testing.T) {
 		resp := connect.NewResponse(&bytes.Buffer{})
 		resp.Header().Set(CLIWarningHeaderName, base64.StdEncoding.EncodeToString([]byte(warningMessage)))
 		return resp, nil
-	})(context.Background(), connect.NewRequest(&bytes.Buffer{}))
+	})(t.Context(), connect.NewRequest(&bytes.Buffer{}))
 	assert.NoError(t, err)
-	assert.Equal(t, fmt.Sprintf("WARN\t%s\n", warningMessage), buf.String())
+	assertWarnLog(t, warningMessage, buf.String())
 
 	// testing no warning message in valid response with no header
 	buf.Reset()
 	_, err = NewCLIWarningInterceptor(appext.NewLoggerContainer(logger))(func(ctx context.Context, req connect.AnyRequest) (connect.AnyResponse, error) {
 		return connect.NewResponse(&bytes.Buffer{}), nil
-	})(context.Background(), connect.NewRequest(&bytes.Buffer{}))
+	})(t.Context(), connect.NewRequest(&bytes.Buffer{}))
 	assert.NoError(t, err)
 	assert.Equal(t, "", buf.String())
 }
@@ -143,9 +144,9 @@ func TestCLIWarningInterceptorFromError(t *testing.T) {
 		err := connect.NewError(connect.CodeInternal, errors.New("error"))
 		err.Meta().Set(CLIWarningHeaderName, base64.StdEncoding.EncodeToString([]byte(warningMessage)))
 		return nil, err
-	})(context.Background(), connect.NewRequest(&bytes.Buffer{}))
+	})(t.Context(), connect.NewRequest(&bytes.Buffer{}))
 	assert.Error(t, err)
-	assert.Equal(t, fmt.Sprintf("WARN\t%s\n", warningMessage), buf.String())
+	assertWarnLog(t, warningMessage, buf.String())
 }
 
 type testRequest[T any] struct {
@@ -163,12 +164,25 @@ func (r testRequest[_]) Peer() connect.Peer {
 	}
 }
 
+// assertWarnLog verifies that logOutput contains a single WARN log line with the
+// given message. The console handler prepends an RFC3339 timestamp, so this
+// helper parses the three tab-separated fields and checks each one.
+func assertWarnLog(t *testing.T, message, logOutput string) {
+	t.Helper()
+	parts := strings.SplitN(strings.TrimRight(logOutput, "\n"), "\t", 3)
+	require.Len(t, parts, 3, "expected 3 tab-separated fields in log output")
+	_, err := time.Parse(time.RFC3339, parts[0])
+	assert.NoError(t, err, "expected valid RFC3339 timestamp")
+	assert.Equal(t, "WARN", parts[1])
+	assert.Equal(t, message, parts[2])
+}
+
 func TestNewAugmentedConnectErrorInterceptor(t *testing.T) {
 	t.Parallel()
 	_, err := NewAugmentedConnectErrorInterceptor()(func(ctx context.Context, req connect.AnyRequest) (connect.AnyResponse, error) {
 		err := connect.NewError(connect.CodeUnknown, errors.New("405 Method Not Allowed"))
 		return nil, err
-	})(context.Background(), testRequest[bytes.Buffer]{Request: connect.NewRequest(&bytes.Buffer{})})
+	})(t.Context(), testRequest[bytes.Buffer]{Request: connect.NewRequest(&bytes.Buffer{})})
 	assert.Error(t, err)
 	var augmentedConnectError *AugmentedConnectError
 	assert.ErrorAs(t, err, &augmentedConnectError)

private/pkg/slogapp/console.go

@@ -22,6 +22,7 @@ import (
 	"log/slog"
 	"os"
 	"sync"
+	"time"
 
 	"github.com/mattn/go-colorable"
 	"golang.org/x/term"
@@ -132,6 +133,10 @@ func (c *consoleHandler) Handle(ctx context.Context, r slog.Record) error {
 	c.lock.Lock()
 	defer c.lock.Unlock()
 	c.buffer.Reset()
+	if !r.Time.IsZero() {
+		c.buffer.WriteString(r.Time.Format(time.RFC3339))
+		c.buffer.WriteString(consoleSeparator)
+	}
 	if c.enableColor {
 		c.buffer.WriteString(colorize(r.Level.String(), getColor(r.Level)))
 	} else {

private/pkg/slogapp/console_test.go

@@ -22,6 +22,7 @@ import (
 	"os"
 	"strings"
 	"testing"
+	"time"
 
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
@@ -44,7 +45,7 @@ func TestIsWriterTTY(t *testing.T) {
 func TestConsoleLogOutput(t *testing.T) {
 	t.Parallel()
 
-	testConsolLogOutput(t, func(logger *slog.Logger) {
+	testConsoleLogOutput(t, func(logger *slog.Logger) {
 		logger.Info("hello", slog.String("a", "b"))
 		logger.Info("hello world")
 	}, []map[string]any{{
@@ -56,7 +57,7 @@ func TestConsoleLogOutput(t *testing.T) {
 		slog.MessageKey: "hello world",
 	}}, withConsoleColor(true))
 
-	testConsolLogOutput(t, func(logger *slog.Logger) {
+	testConsoleLogOutput(t, func(logger *slog.Logger) {
 		logger.Info("info", slog.String("a", "b"))
 		logger.Error("error")
 	}, []map[string]any{{
@@ -68,7 +69,7 @@ func TestConsoleLogOutput(t *testing.T) {
 		slog.MessageKey: "error",
 	}})
 
-	testConsolLogOutput(t, func(logger *slog.Logger) {
+	testConsoleLogOutput(t, func(logger *slog.Logger) {
 		logger = logger.With(slog.String("a", "b"))
 		logger = logger.WithGroup("g")
 		logger.Error("error message", slog.String("c", "d"))
@@ -87,7 +88,7 @@ func TestConsoleLogOutput(t *testing.T) {
 		"a":             "b",
 	}}, withConsoleColor(true))
 
-	testConsolLogOutput(t, func(logger *slog.Logger) {
+	testConsoleLogOutput(t, func(logger *slog.Logger) {
 		logger.Info("key spaces", slog.String("a key", "with spaces"))
 	}, []map[string]any{{
 		slog.LevelKey:   colorize("INFO", getColor(slog.LevelInfo)),
@@ -96,7 +97,7 @@ func TestConsoleLogOutput(t *testing.T) {
 	}}, withConsoleColor(true))
 }
 
-func testConsolLogOutput(t *testing.T, run func(logger *slog.Logger), expects []map[string]any, options ...consoleHandlerOption) {
+func testConsoleLogOutput(t *testing.T, run func(logger *slog.Logger), expects []map[string]any, options ...consoleHandlerOption) {
 	t.Helper()
 	var buf bytes.Buffer
 	consoleHandler := newConsoleHandler(&buf, slog.LevelInfo, options...)
@@ -118,16 +119,31 @@ func testConsolLogOutput(t *testing.T, run func(logger *slog.Logger), expects []
 	require.Equal(t, len(expects), len(outputs))
 	for i := range len(outputs) {
 		output, expect := outputs[i], expects[i]
+		// Verify the timestamp is present and parseable, then remove it before
+		// comparing the rest of the output (timestamps are dynamic).
+		ts, ok := output[slog.TimeKey]
+		if assert.True(t, ok, "expected timestamp in log output") {
+			timestamp, ok := ts.(string)
+			assert.True(t, ok, "expected timestamp to be string type in log output")
+			_, err := time.Parse(time.RFC3339, timestamp)
+			assert.NoError(t, err, "timestamp should be valid RFC3339")
+		}
+		delete(output, slog.TimeKey)
 		assert.Equal(t, expect, output)
 	}
 }
 
-// testParseLogLine passes the output of a single log line.
+// testParseLogLine parses the output of a single log line.
+// The format is: TIME\tLEVEL\tMESSAGE\t{...JSON attrs...}\n
 func testParseLogLine(lineBytes []byte) (map[string]any, error) {
 	top := map[string]any{}
 	line := string(bytes.TrimSpace(lineBytes))
-	index, line, _ := strings.Cut(line, consoleSeparator)
-	top[slog.LevelKey] = index
+	// First field is the timestamp.
+	timestamp, line, _ := strings.Cut(line, consoleSeparator)
+	top[slog.TimeKey] = timestamp
+	// Second field is the level.
+	level, line, _ := strings.Cut(line, consoleSeparator)
+	top[slog.LevelKey] = level
 	if len(line) == 0 {
 		return top, nil
 	}