Add timestamp to console logs

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/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
 	}