text_formatter_test.go

package logrus

import (
	"bytes"
	"errors"
	"fmt"
	"os"
	"runtime"
	"slices"
	"sort"
	"strings"
	"testing"
	"time"

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

func TestFormatting(t *testing.T) {
	tf := &TextFormatter{DisableColors: true}

	testCases := []struct {
		value    string
		expected string
	}{
		{`foo`, "time=\"0001-01-01T00:00:00Z\" level=panic test=foo\n"},
	}

	for _, tc := range testCases {
		b, _ := tf.Format(WithField("test", tc.value))

		if string(b) != tc.expected {
			t.Errorf("formatting expected for %q (result was %q instead of %q)", tc.value, string(b), tc.expected)
		}
	}
}

func TestQuoting(t *testing.T) {
	tf := &TextFormatter{DisableColors: true}

	checkQuoting := func(q bool, value any) {
		b, _ := tf.Format(WithField("test", value))
		_, after, _ := bytes.Cut(b, ([]byte)("test="))
		cont := bytes.Contains(after, []byte("\""))
		if cont != q {
			if q {
				t.Errorf("quoting expected for: %#v", value)
			} else {
				t.Errorf("quoting not expected for: %#v", value)
			}
		}
	}

	checkQuoting(false, "")
	checkQuoting(false, "abcd")
	checkQuoting(false, "v1.0")
	checkQuoting(false, "1234567890")
	checkQuoting(false, "/foobar")
	checkQuoting(false, "foo_bar")
	checkQuoting(false, "foo@bar")
	checkQuoting(false, "foobar^")
	checkQuoting(false, "+/-_^@f.oobar")
	checkQuoting(true, "foo\n\rbar")
	checkQuoting(true, "foobar$")
	checkQuoting(true, "&foobar")
	checkQuoting(true, "x y")
	checkQuoting(true, "x,y")

	// New/explicit: bool fast path (never needs quoting unless forced).
	checkQuoting(false, true)
	checkQuoting(false, false)

	// New/explicit: numeric fast path (never needs quoting unless forced).
	checkQuoting(false, 0)
	checkQuoting(false, int64(-123))
	checkQuoting(false, uint64(123))
	checkQuoting(false, float64(3.14))

	// New/explicit: []byte fast path.
	checkQuoting(false, []byte("abcd"))
	checkQuoting(true, []byte("x y"))

	// Error path (string fast path via Error()).
	checkQuoting(false, errors.New("invalid"))
	checkQuoting(true, errors.New("invalid argument"))

	// Test for quoting empty fields.
	tf.QuoteEmptyFields = true
	checkQuoting(true, "")
	checkQuoting(false, "abcd")
	checkQuoting(true, "foo\n\rbar")
	checkQuoting(true, errors.New("invalid argument"))

	// New/explicit: QuoteEmptyFields shouldn't affect non-empty primitives.
	checkQuoting(false, 0)
	checkQuoting(false, true)
	checkQuoting(false, []byte("abcd"))

	// Test forcing quotes.
	tf.ForceQuote = true
	checkQuoting(true, "")
	checkQuoting(true, "abcd")
	checkQuoting(true, "foo\n\rbar")
	checkQuoting(true, errors.New("invalid argument"))

	// New/explicit: ForceQuote should quote numeric/bool/[]byte too.
	checkQuoting(true, 0)
	checkQuoting(true, true)
	checkQuoting(true, []byte("abcd"))

	// Test forcing quotes when also disabling them.
	tf.DisableQuote = true
	checkQuoting(true, "")
	checkQuoting(true, "abcd")
	checkQuoting(true, "foo\n\rbar")
	checkQuoting(true, errors.New("invalid argument"))

	// Test disabling quotes
	tf.ForceQuote = false
	tf.QuoteEmptyFields = false
	checkQuoting(false, "")
	checkQuoting(false, "abcd")
	checkQuoting(false, "foo\n\rbar")
	checkQuoting(false, errors.New("invalid argument"))

	// New/explicit: DisableQuote should keep primitives unquoted.
	checkQuoting(false, 0)
	checkQuoting(false, true)
	checkQuoting(false, []byte("x y"))
}

func TestEscaping(t *testing.T) {
	tf := &TextFormatter{DisableColors: true}

	testCases := []struct {
		value    string
		expected string
	}{
		{`ba"r`, `ba\"r`},
		{`ba'r`, `ba'r`},
	}

	for _, tc := range testCases {
		b, _ := tf.Format(WithField("test", tc.value))
		if !bytes.Contains(b, []byte(tc.expected)) {
			t.Errorf("escaping expected for %q (result was %q instead of %q)", tc.value, string(b), tc.expected)
		}
	}
}

func TestEscaping_Interface(t *testing.T) {
	tf := &TextFormatter{DisableColors: true}

	ts := time.Now()

	testCases := []struct {
		value    any
		expected string
	}{
		{ts, fmt.Sprintf("\"%s\"", ts.String())},
		{errors.New("error: something went wrong"), "\"error: something went wrong\""},
	}

	for _, tc := range testCases {
		b, _ := tf.Format(WithField("test", tc.value))
		if !bytes.Contains(b, []byte(tc.expected)) {
			t.Errorf("escaping expected for %q (result was %q instead of %q)", tc.value, string(b), tc.expected)
		}
	}
}

func TestTimestampFormat(t *testing.T) {
	checkTimeStr := func(format string) {
		customFormatter := &TextFormatter{DisableColors: true, TimestampFormat: format}
		customStr, _ := customFormatter.Format(WithField("test", "test"))
		timeStart := bytes.Index(customStr, ([]byte)("time="))
		timeEnd := bytes.Index(customStr, ([]byte)("level="))
		timeStr := customStr[timeStart+5+len("\"") : timeEnd-1-len("\"")]
		if format == "" {
			format = time.RFC3339
		}
		_, e := time.Parse(format, (string)(timeStr))
		if e != nil {
			t.Errorf("time string \"%s\" did not match provided time format \"%s\": %s", timeStr, format, e)
		}
	}

	checkTimeStr("2006-01-02T15:04:05.000000000Z07:00")
	checkTimeStr("Mon Jan _2 15:04:05 2006")
	checkTimeStr("")
}

func TestDisableLevelTruncation(t *testing.T) {
	entry := &Entry{
		Time:    time.Now(),
		Message: "testing",
	}
	checkDisableTruncation := func(disabled bool, level Level) {
		tf := &TextFormatter{
			DisableLevelTruncation: disabled,
			ForceColors:            true,
			DisableTimestamp:       true,
		}
		entry.Level = level
		out, err := tf.Format(entry)
		if err != nil {
			t.Errorf("error formatting log entry: %s", err)
		}
		logLine := string(out)
		if disabled {
			expected := strings.ToUpper(level.String())
			if !strings.Contains(logLine, expected) {
				t.Errorf("level string expected to be %s when truncation disabled", expected)
			}
		} else {
			expected := strings.ToUpper(level.String())
			if len(level.String()) > 4 {
				if strings.Contains(logLine, expected) {
					t.Errorf("level string %s expected to be truncated to %s when truncation is enabled", expected, expected[0:4])
				}
			} else {
				if !strings.Contains(logLine, expected) {
					t.Errorf("level string expected to be %s when truncation is enabled and level string is below truncation threshold", expected)
				}
			}
		}
	}

	checkDisableTruncation(true, DebugLevel)
	checkDisableTruncation(true, InfoLevel)
	checkDisableTruncation(false, ErrorLevel)
	checkDisableTruncation(false, InfoLevel)
}

func TestPadLevelText(t *testing.T) {
	// A note for future maintainers / committers:
	//
	// This test denormalizes the level text as a part of its assertions.
	// Because of that, its not really a "unit test" of the PadLevelText functionality.
	// So! Many apologies to the potential future person who has to rewrite this test
	// when they are changing some completely unrelated functionality.
	params := []struct {
		name            string
		level           Level
		paddedLevelText string
	}{
		{
			name:            "PanicLevel",
			level:           PanicLevel,
			paddedLevelText: "PANIC  ", // 2 extra spaces
		},
		{
			name:            "FatalLevel",
			level:           FatalLevel,
			paddedLevelText: "FATAL  ", // 2 extra spaces
		},
		{
			name:            "ErrorLevel",
			level:           ErrorLevel,
			paddedLevelText: "ERROR  ", // 2 extra spaces
		},
		{
			name:  "WarnLevel",
			level: WarnLevel,
			// WARNING is already the max length, so we don't need to assert a paddedLevelText
		},
		{
			name:            "DebugLevel",
			level:           DebugLevel,
			paddedLevelText: "DEBUG  ", // 2 extra spaces
		},
		{
			name:            "TraceLevel",
			level:           TraceLevel,
			paddedLevelText: "TRACE  ", // 2 extra spaces
		},
		{
			name:            "InfoLevel",
			level:           InfoLevel,
			paddedLevelText: "INFO   ", // 3 extra spaces
		},
	}

	// We create a "default" TextFormatter to do a control test.
	// We also create a TextFormatter with PadLevelText, which is the parameter we want to do our most relevant assertions against.
	tfDefault := TextFormatter{ForceColors: true}
	tfWithPadding := TextFormatter{ForceColors: true, PadLevelText: true}

	for _, val := range params {
		t.Run(val.name, func(t *testing.T) {
			out, err := tfDefault.Format(&Entry{Level: val.level})
			if err != nil {
				t.Errorf("error formatting log entry: %s", err)
			}
			logLineDefault := string(out)

			out, err = tfWithPadding.Format(&Entry{Level: val.level})
			if err != nil {
				t.Errorf("error formatting log entry: %s", err)
			}
			logLineWithPadding := string(out)

			// Control: the level text should not be padded by default
			if val.paddedLevelText != "" && strings.Contains(logLineDefault, val.paddedLevelText) {
				t.Errorf("log line %q should not contain the padded level text %q by default", logLineDefault, val.paddedLevelText)
			}

			// Assertion: the level text should still contain the string representation of the level
			if !strings.Contains(strings.ToLower(logLineWithPadding), val.level.String()) {
				t.Errorf("log line %q should contain the level text %q when padding is enabled", logLineWithPadding, val.level.String())
			}

			// Assertion: the level text should be in its padded form now
			if val.paddedLevelText != "" && !strings.Contains(logLineWithPadding, val.paddedLevelText) {
				t.Errorf("log line %q should contain the padded level text %q when padding is enabled", logLineWithPadding, val.paddedLevelText)
			}
		})
	}
}

func TestDisableTimestampWithColoredOutput(t *testing.T) {
	tf := &TextFormatter{DisableTimestamp: true, ForceColors: true}

	b, _ := tf.Format(WithField("test", "test"))
	if strings.Contains(string(b), "[0000]") {
		t.Error("timestamp not expected when DisableTimestamp is true")
	}
}

func TestNewlineBehavior(t *testing.T) {
	tf := &TextFormatter{ForceColors: true}

	// Ensure a single new line is removed as per stdlib log
	e := NewEntry(StandardLogger())
	e.Message = "test message\n"
	b, _ := tf.Format(e)
	if bytes.Contains(b, []byte("test message\n")) {
		t.Error("first newline at end of Entry.Message resulted in unexpected 2 newlines in output. Expected newline to be removed.")
	}

	// Ensure a double new line is reduced to a single new line
	e = NewEntry(StandardLogger())
	e.Message = "test message\n\n"
	b, _ = tf.Format(e)
	if bytes.Contains(b, []byte("test message\n\n")) {
		t.Error("Double newline at end of Entry.Message resulted in unexpected 2 newlines in output. Expected single newline")
	}
	if !bytes.Contains(b, []byte("test message\n")) {
		t.Error("Double newline at end of Entry.Message did not result in a single newline after formatting")
	}
}

func TestTextFormatterFieldMap(t *testing.T) {
	formatter := &TextFormatter{
		DisableColors: true,
		FieldMap: FieldMap{
			FieldKeyMsg:   "message",
			FieldKeyLevel: "somelevel",
			FieldKeyTime:  "timeywimey",
		},
	}

	entry := &Entry{
		Message: "oh hi",
		Level:   WarnLevel,
		Time:    time.Date(1981, time.February, 24, 4, 28, 3, 100, time.UTC),
		Data: Fields{
			"field1":     "f1",
			"message":    "messagefield",
			"somelevel":  "levelfield",
			"timeywimey": "timeywimeyfield",
		},
	}

	b, err := formatter.Format(entry)
	if err != nil {
		t.Fatal("Unable to format entry: ", err)
	}

	assert.Equal(t,
		`timeywimey="1981-02-24T04:28:03Z" `+
			`somelevel=warning `+
			`message="oh hi" `+
			`field1=f1 `+
			`fields.message=messagefield `+
			`fields.somelevel=levelfield `+
			`fields.timeywimey=timeywimeyfield`+"\n",
		string(b),
		"Formatted output doesn't respect FieldMap")
}

func TestTextFormatterIsColored(t *testing.T) {
	tests := []struct {
		name         string
		expected     bool
		isTerminal   bool
		disableColor bool
		forceColors  bool
		envVars      []string
	}{
		{
			// Default values
			name: "default",
		},
		{
			// Output on terminal
			name:       "tty",
			expected:   true,
			isTerminal: true,
		},
		{
			// Output on terminal with color disabled
			name:         "tty,DisableColors=1",
			expected:     false,
			isTerminal:   true,
			disableColor: true,
		},
		{
			// Output not on terminal with color disabled
			name:         "DisableColors=1",
			expected:     false,
			disableColor: true,
		},
		{
			// Output not on terminal with color forced
			name:        "ForceColors=1",
			expected:    true,
			forceColors: true,
		},
		{
			// Output on terminal with clicolor set to "0"
			name:       "tty,CLICOLOR=0",
			expected:   false,
			isTerminal: true,
			envVars:    []string{"CLICOLOR=0"},
		},
		{
			// Output on terminal with clicolor set to "1"
			name:       "tty,CLICOLOR=1",
			expected:   true,
			isTerminal: true,
			envVars:    []string{"CLICOLOR=1"},
		},
		{
			// Output not on terminal with clicolor set to "0"
			name:     "CLICOLOR=0",
			expected: false,
			envVars:  []string{"CLICOLOR=0"},
		},
		{
			// Output not on terminal with clicolor set to "1"
			name:     "CLICOLOR=1",
			expected: false,
			envVars:  []string{"CLICOLOR=1"},
		},
		{
			// Output not on terminal with clicolor set to "1" and force color
			name:        "ForceColors=1,CLICOLOR=1",
			expected:    true,
			forceColors: true,
			envVars:     []string{"CLICOLOR=1"},
		},
		{
			// Output not on terminal with clicolor set to "0" and force color
			name:        "ForceColors=1,CLICOLOR=0",
			expected:    false,
			forceColors: true,
			envVars:     []string{"CLICOLOR=0"},
		},
		{
			// Output not on terminal with clicolor_force set to "1"
			name:     "CLICOLOR_FORCE=1",
			expected: true,
			envVars:  []string{"CLICOLOR_FORCE=1"},
		},
		{
			// Output not on terminal with clicolor_force set to "0"
			name:     "CLICOLOR_FORCE=0",
			expected: false,
			envVars:  []string{"CLICOLOR_FORCE=0"},
		},
		{
			// Output on terminal with clicolor_force set to "0"
			name:       "tty,CLICOLOR_FORCE=0",
			expected:   false,
			isTerminal: true,
			envVars:    []string{"CLICOLOR_FORCE=0"},
		},
	}

	for _, tc := range tests {
		t.Run(tc.name, func(t *testing.T) {
			// Unset existing vars to prevent them from interfering with the test.
			unsetEnv(t, "CLICOLOR")
			unsetEnv(t, "CLICOLOR_FORCE")
			for _, envVar := range tc.envVars {
				k, v, _ := strings.Cut(envVar, "=")
				t.Setenv(k, v)
			}
			tf := TextFormatter{
				DisableColors:             tc.disableColor,
				ForceColors:               tc.forceColors,
				EnvironmentOverrideColors: len(tc.envVars) > 0,
			}

			expected := tc.expected
			if runtime.GOOS == "windows" && !tc.forceColors && os.Getenv("CLICOLOR_FORCE") == "" {
				// On Windows, without ForceColors or CLICOLOR_FORCE, colors are disabled.
				expected = false
			}

			// TODO(thaJeztah): need a way to mock "isTerminal" and check "isColored" for testing
			//  without depending on non-exported methods and fields.
			res := tf.isColored(tc.isTerminal) // tc.isTerminal avoids depending on a real TTY
			assert.Equal(t, expected, res)
		})
	}
}

// unsetEnv calls [os.Unsetenv] to unset an environment
// variable if it is set, and uses t.Cleanup to restore
// the environment variable to its original value after
// the test.
//
// Because unsetEnv affects the whole process, it should
// not be used in parallel tests or tests with parallel
// ancestors.
func unsetEnv(t *testing.T, env string) {
	t.Helper()
	prevValue, ok := os.LookupEnv(env)
	if ok {
		_ = os.Unsetenv(env)
		t.Cleanup(func() {
			_ = os.Setenv(env, prevValue)
		})
	}
}

func TestCustomSorting(t *testing.T) {
	formatter := &TextFormatter{
		DisableColors: true,
		SortingFunc: func(keys []string) {
			sort.Slice(keys, func(i, j int) bool {
				if keys[j] == "prefix" {
					return false
				}
				if keys[i] == "prefix" {
					return true
				}
				return strings.Compare(keys[i], keys[j]) == -1
			})
		},
	}

	entry := &Entry{
		Message: "Testing custom sort function",
		Time:    time.Now(),
		Level:   InfoLevel,
		Data: Fields{
			"test":      "testvalue",
			"prefix":    "the application prefix",
			"blablabla": "blablabla",
		},
	}
	b, err := formatter.Format(entry)
	require.NoError(t, err)
	require.True(t, strings.HasPrefix(string(b), "prefix="), "format output is %q", string(b))
}

// TestCustomSorting_FirstFormat tests that color and terminal settings
// are performed on the first message, and the message is properly
// formatted with default (fixedKeys) fields excluded.
//
// regression test for https://github.com/sirupsen/logrus/issues/1298
func TestCustomSorting_FirstFormat(t *testing.T) {
	if runtime.GOOS == "windows" {
		t.Skip("colored output not supported on Windows")
	}
	if !checkIfTerminal(os.Stderr) {
		t.Skip("test requires a TTY")
	}

	t.Setenv("CLICOLOR", "")
	t.Setenv("CLICOLOR_FORCE", "")

	logger := New()
	logger.SetOutput(os.Stderr) // don't discard output; we need terminal detection
	entry := &Entry{
		Logger:  logger,
		Message: `colored messages are pretty`,
		Level:   InfoLevel,
		Data:    Fields{"z": 2, "a": 1},
	}

	var sortCalled bool
	var otherFields []string
	tf := &TextFormatter{
		DisableTimestamp: true,
		SortingFunc: func(keys []string) {
			sortCalled = true
			slices.Sort(keys)
			for _, key := range keys {
				if _, ok := entry.Data[key]; !ok {
					// default ("fixedKeys") should not be included when printing colored.
					otherFields = append(otherFields, key)
				}
			}
		},
	}
	for _, name := range []string{"first", "second"} {
		t.Run(name, func(t *testing.T) {
			sortCalled = false
			otherFields = []string{}
			out, err := tf.Format(entry)
			require.NoError(t, err)
			assert.True(t, sortCalled)
			assert.Empty(t, otherFields)

			// sanity checks:
			assert.Contains(t, string(out), "\x1b[") // ANSI present
			assert.Contains(t, string(out), "colored messages are pretty")
		})
	}
}

func TestTextEntryFieldValueError(t *testing.T) {
	t.Run("good value", func(t *testing.T) {
		var buf bytes.Buffer
		l := New()
		l.SetOutput(&buf)
		l.SetFormatter(&TextFormatter{DisableTimestamp: true, DisableColors: true})

		l.WithField("ok", "ok").Info("test")

		out := buf.String()
		if field := FieldKeyLogrusError + "="; strings.Contains(out, field) {
			t.Errorf(`Unexpected "logrus_error" field in log entry: %v`, out)
		}
		if field := `ok=ok`; !strings.Contains(out, field) {
			t.Errorf(`Expected log entry to contain "ok=ok": %v`, out)
		}
	})

	// If we dropped an unsupported field, the FieldKeyLogrusError should
	// contain a message that we did.
	t.Run("bad and good value", func(t *testing.T) {
		var buf bytes.Buffer
		l := New()
		l.SetOutput(&buf)
		l.SetFormatter(&TextFormatter{DisableTimestamp: true, DisableColors: true})

		l.WithField("func", func() {}).WithField("ok", "ok").Info("test")

		out := buf.String()
		if field := FieldKeyLogrusError + "="; !strings.Contains(out, field) {
			t.Errorf(`Expected log entry to contain a "logrus_error" field: %v`, out)
		}
		if field := `func=`; strings.Contains(out, field) {
			t.Errorf(`Expected "func" field to be removed from log entry: %v`, out)
		}
		if field := `ok=ok`; !strings.Contains(out, field) {
			t.Errorf(`Expected log entry to contain "ok=ok": %v`, out)
		}

	})

	// This is testing the current behavior; error is preserved, even if an
	// unsupported value was dropped and replaced with a supported value for
	// the same field.
	t.Run("replace bad value", func(t *testing.T) {
		var buf bytes.Buffer
		l := New()
		l.SetOutput(&buf)
		l.SetFormatter(&TextFormatter{DisableTimestamp: true, DisableColors: true})

		l.WithField("func", func() {}).WithField("ok", "ok").WithField("func", "not-a-func").Info("test")

		out := buf.String()
		if field := FieldKeyLogrusError + "="; !strings.Contains(out, field) {
			t.Errorf(`Expected log entry to contain a "logrus_error" field: %v`, out)
		}
		if field := `func=not-a-func`; !strings.Contains(out, field) {
			t.Errorf(`Expected log entry to contain "func=not-a-func": %v`, out)
		}
		if field := `ok=ok`; !strings.Contains(out, field) {
			t.Errorf(`Expected log entry to contain "ok=ok": %v`, out)
		}
	})
}