rclone/fs/log/slog_test.go

package log

import (
	"bytes"
	"context"
	"fmt"
	"os"
	"regexp"
	"strings"
	"testing"
	"time"

	"log/slog"

	"github.com/rclone/rclone/fs"
	"github.com/stretchr/testify/assert"
	"github.com/stretchr/testify/require"
)

var (
	utcPlusOne = time.FixedZone("UTC+1", 1*60*60)
	t0         = time.Date(2020, 1, 2, 3, 4, 5, 123456000, utcPlusOne)
)

// Test slogLevelToString covers all mapped levels and an unknown level.
func TestSlogLevelToString(t *testing.T) {
	tests := []struct {
		level slog.Level
		want  string
	}{
		{slog.LevelDebug, "DEBUG"},
		{slog.LevelInfo, "INFO"},
		{fs.SlogLevelNotice, "NOTICE"},
		{slog.LevelWarn, "WARNING"},
		{slog.LevelError, "ERROR"},
		{fs.SlogLevelCritical, "CRITICAL"},
		{fs.SlogLevelAlert, "ALERT"},
		{fs.SlogLevelEmergency, "EMERGENCY"},
		// Unknown level should fall back to .String()
		{slog.Level(1234), slog.Level(1234).String()},
	}
	for _, tc := range tests {
		got := slogLevelToString(tc.level)
		assert.Equal(t, tc.want, got)
	}
}

// Test mapLogLevelNames replaces only the LevelKey attr and lowercases it.
func TestMapLogLevelNames(t *testing.T) {
	a := slog.Any(slog.LevelKey, slog.LevelWarn)
	mapped := mapLogLevelNames(nil, a)
	val, ok := mapped.Value.Any().(string)
	if !ok || val != "warning" {
		t.Errorf("mapLogLevelNames did not lowercase level: got %v", mapped.Value.Any())
	}
	// non-level attr should remain unchanged
	other := slog.String("foo", "bar")
	out := mapLogLevelNames(nil, other)
	assert.Equal(t, out.Value, other.Value, "mapLogLevelNames changed a non-level attr")
}

// Test getCaller returns a file:line string of the correct form.
func TestGetCaller(t *testing.T) {
	out := getCaller(0)
	assert.NotEqual(t, "", out)
	match := regexp.MustCompile(`^([^:]+):(\d+)$`).FindStringSubmatch(out)
	assert.NotNil(t, match)
	// Can't test this as it skips the /log/ directory!
	// assert.Equal(t, "slog_test.go", match[1])
}

// Test formatStdLogHeader for various flag combinations.
func TestFormatStdLogHeader(t *testing.T) {
	cases := []struct {
		name       string
		format     logFormat
		lineInfo   string
		object     string
		wantPrefix string
	}{
		{"dateTime", logFormatDate | logFormatTime, "", "", "2020/01/02 03:04:05 "},
		{"time", logFormatTime, "", "", "03:04:05 "},
		{"date", logFormatDate, "", "", "2020/01/02 "},
		{"dateTimeUTC", logFormatDate | logFormatTime | logFormatUTC, "", "", "2020/01/02 02:04:05 "},
		{"dateTimeMicro", logFormatDate | logFormatTime | logFormatMicroseconds, "", "", "2020/01/02 03:04:05.123456 "},
		{"micro", logFormatMicroseconds, "", "", "03:04:05.123456 "},
		{"shortFile", logFormatShortFile, "foo.go:10", "03:04:05 ", "foo.go:10: "},
		{"longFile", logFormatLongFile, "foo.go:10", "03:04:05 ", "foo.go:10: "},
		{"timePID", logFormatPid, "", "", fmt.Sprintf("[%d] ", os.Getpid())},
		{"levelObject", 0, "", "myobj", "INFO  : myobj: "},
	}
	for _, tc := range cases {
		t.Run(tc.name, func(t *testing.T) {
			h := &OutputHandler{format: tc.format}
			buf := &bytes.Buffer{}
			h.formatStdLogHeader(buf, slog.LevelInfo, t0, tc.object, tc.lineInfo)
			if !strings.HasPrefix(buf.String(), tc.wantPrefix) {
				t.Errorf("%s: got %q; want prefix %q", tc.name, buf.String(), tc.wantPrefix)
			}
		})
	}
}

// Test Enabled honors the HandlerOptions.Level.
func TestEnabled(t *testing.T) {
	h := NewOutputHandler(&bytes.Buffer{}, nil, 0)
	assert.True(t, h.Enabled(context.Background(), slog.LevelInfo))
	assert.False(t, h.Enabled(context.Background(), slog.LevelDebug))

	opts := &slog.HandlerOptions{Level: slog.LevelDebug}
	h2 := NewOutputHandler(&bytes.Buffer{}, opts, 0)
	assert.True(t, h2.Enabled(context.Background(), slog.LevelDebug))
}

// Test clearFormatFlags and setFormatFlags bitwise ops.
func TestClearSetFormatFlags(t *testing.T) {
	h := &OutputHandler{format: logFormatDate | logFormatTime}

	h.clearFormatFlags(logFormatTime)
	assert.True(t, h.format&logFormatTime == 0)

	h.setFormatFlags(logFormatMicroseconds)
	assert.True(t, h.format&logFormatMicroseconds != 0)
}

// Test SetOutput and ResetOutput override the default writer.
func TestSetResetOutput(t *testing.T) {
	buf := &bytes.Buffer{}
	h := NewOutputHandler(buf, nil, 0)
	var gotOverride string
	out := func(_ slog.Level, txt string) {
		gotOverride = txt
	}

	h.SetOutput(out)
	r := slog.NewRecord(t0, slog.LevelInfo, "hello", 0)
	require.NoError(t, h.Handle(context.Background(), r))
	assert.NotEqual(t, "", gotOverride)
	require.Equal(t, "", buf.String())

	h.ResetOutput()
	require.NoError(t, h.Handle(context.Background(), r))
	require.NotEqual(t, "", buf.String())
}

// Test AddOutput sends to extra destinations.
func TestAddOutput(t *testing.T) {
	buf := &bytes.Buffer{}
	h := NewOutputHandler(buf, nil, logFormatDate|logFormatTime)
	var extraText string
	out := func(_ slog.Level, txt string) {
		extraText = txt
	}

	h.AddOutput(false, out)

	r := slog.NewRecord(t0, slog.LevelInfo, "world", 0)
	require.NoError(t, h.Handle(context.Background(), r))
	assert.Equal(t, "2020/01/02 03:04:05 INFO  : world\n", buf.String())
	assert.Equal(t, "2020/01/02 03:04:05 INFO  : world\n", extraText)
}

// Test AddOutputJSON sends JSON to extra destinations.
func TestAddOutputJSON(t *testing.T) {
	buf := &bytes.Buffer{}
	h := NewOutputHandler(buf, nil, logFormatDate|logFormatTime)
	var extraText string
	out := func(_ slog.Level, txt string) {
		extraText = txt
	}

	h.AddOutput(true, out)

	r := slog.NewRecord(t0, slog.LevelInfo, "world", 0)
	require.NoError(t, h.Handle(context.Background(), r))
	assert.NotEqual(t, "", extraText)
	assert.Equal(t, "2020/01/02 03:04:05 INFO  : world\n", buf.String())
	assert.True(t, strings.HasPrefix(extraText, `{"time":"2020-01-02T03:04:05.123456+01:00","level":"info","msg":"world","source":"`))
	assert.True(t, strings.HasSuffix(extraText, "\"}\n"))
}

// Test AddOutputUseJSONLog sends text to extra destinations.
func TestAddOutputUseJSONLog(t *testing.T) {
	buf := &bytes.Buffer{}
	h := NewOutputHandler(buf, nil, logFormatDate|logFormatTime|logFormatJSON)
	var extraText string
	out := func(_ slog.Level, txt string) {
		extraText = txt
	}

	h.AddOutput(false, out)

	r := slog.NewRecord(t0, slog.LevelInfo, "world", 0)
	require.NoError(t, h.Handle(context.Background(), r))
	assert.NotEqual(t, "", extraText)
	assert.True(t, strings.HasPrefix(buf.String(), `{"time":"2020-01-02T03:04:05.123456+01:00","level":"info","msg":"world","source":"`))
	assert.True(t, strings.HasSuffix(buf.String(), "\"}\n"))
	assert.Equal(t, "2020/01/02 03:04:05 INFO  : world\n", extraText)
}

// Test WithAttrs and WithGroup return new handlers with same settings.
func TestWithAttrsAndGroup(t *testing.T) {
	buf := &bytes.Buffer{}
	h := NewOutputHandler(buf, nil, logFormatDate)
	h2 := h.WithAttrs([]slog.Attr{slog.String("k", "v")})
	if _, ok := h2.(*OutputHandler); !ok {
		t.Error("WithAttrs returned wrong type")
	}
	h3 := h.WithGroup("grp")
	if _, ok := h3.(*OutputHandler); !ok {
		t.Error("WithGroup returned wrong type")
	}
}

// Test textLog and jsonLog directly for basic correctness.
func TestTextLogAndJsonLog(t *testing.T) {
	h := NewOutputHandler(&bytes.Buffer{}, nil, logFormatDate|logFormatTime)
	r := slog.NewRecord(t0, slog.LevelWarn, "msg!", 0)
	r.AddAttrs(slog.String("object", "obj"))

	// textLog
	bufText := &bytes.Buffer{}
	require.NoError(t, h.textLog(context.Background(), bufText, r))
	out := bufText.String()
	if !strings.Contains(out, "WARNING") || !strings.Contains(out, "obj:") || !strings.HasSuffix(out, "\n") {
		t.Errorf("textLog output = %q", out)
	}

	// jsonLog
	bufJSON := &bytes.Buffer{}
	require.NoError(t, h.jsonLog(context.Background(), bufJSON, r))
	j := bufJSON.String()
	if !strings.Contains(j, `"level":"warning"`) || !strings.Contains(j, `"msg":"msg!"`) {
		t.Errorf("jsonLog output = %q", j)
	}
}

// Table-driven test for JSON vs text Handle behavior.
func TestHandleFormatFlags(t *testing.T) {
	r := slog.NewRecord(t0, slog.LevelInfo, "hi", 0)
	cases := []struct {
		name     string
		format   logFormat
		wantJSON bool
	}{
		{"textMode", 0, false},
		{"jsonMode", logFormatJSON, true},
	}
	for _, tc := range cases {
		buf := &bytes.Buffer{}
		h := NewOutputHandler(buf, nil, tc.format)
		require.NoError(t, h.Handle(context.Background(), r))
		out := buf.String()
		if tc.wantJSON {
			if !strings.HasPrefix(out, "{") || !strings.Contains(out, `"level":"info"`) {
				t.Errorf("%s: got %q; want JSON", tc.name, out)
			}
		} else {
			if !strings.Contains(out, "INFO") {
				t.Errorf("%s: got %q; want text INFO", tc.name, out)
			}
		}
	}
}