text_formatter_test.go

Documentation: github.com/sirupsen/logrus

     1  package logrus
     2  
     3  import (
     4  	"bytes"
     5  	"errors"
     6  	"fmt"
     7  	"os"
     8  	"runtime"
     9  	"sort"
    10  	"strings"
    11  	"testing"
    12  	"time"
    13  
    14  	"github.com/stretchr/testify/assert"
    15  	"github.com/stretchr/testify/require"
    16  )
    17  
    18  func TestFormatting(t *testing.T) {
    19  	tf := &TextFormatter{DisableColors: true}
    20  
    21  	testCases := []struct {
    22  		value    string
    23  		expected string
    24  	}{
    25  		{`foo`, "time=\"0001-01-01T00:00:00Z\" level=panic test=foo\n"},
    26  	}
    27  
    28  	for _, tc := range testCases {
    29  		b, _ := tf.Format(WithField("test", tc.value))
    30  
    31  		if string(b) != tc.expected {
    32  			t.Errorf("formatting expected for %q (result was %q instead of %q)", tc.value, string(b), tc.expected)
    33  		}
    34  	}
    35  }
    36  
    37  func TestQuoting(t *testing.T) {
    38  	tf := &TextFormatter{DisableColors: true}
    39  
    40  	checkQuoting := func(q bool, value interface{}) {
    41  		b, _ := tf.Format(WithField("test", value))
    42  		idx := bytes.Index(b, ([]byte)("test="))
    43  		cont := bytes.Contains(b[idx+5:], []byte("\""))
    44  		if cont != q {
    45  			if q {
    46  				t.Errorf("quoting expected for: %#v", value)
    47  			} else {
    48  				t.Errorf("quoting not expected for: %#v", value)
    49  			}
    50  		}
    51  	}
    52  
    53  	checkQuoting(false, "")
    54  	checkQuoting(false, "abcd")
    55  	checkQuoting(false, "v1.0")
    56  	checkQuoting(false, "1234567890")
    57  	checkQuoting(false, "/foobar")
    58  	checkQuoting(false, "foo_bar")
    59  	checkQuoting(false, "foo@bar")
    60  	checkQuoting(false, "foobar^")
    61  	checkQuoting(false, "+/-_^@f.oobar")
    62  	checkQuoting(true, "foo\n\rbar")
    63  	checkQuoting(true, "foobar$")
    64  	checkQuoting(true, "&foobar")
    65  	checkQuoting(true, "x y")
    66  	checkQuoting(true, "x,y")
    67  	checkQuoting(false, errors.New("invalid"))
    68  	checkQuoting(true, errors.New("invalid argument"))
    69  
    70  	// Test for quoting empty fields.
    71  	tf.QuoteEmptyFields = true
    72  	checkQuoting(true, "")
    73  	checkQuoting(false, "abcd")
    74  	checkQuoting(true, "foo\n\rbar")
    75  	checkQuoting(true, errors.New("invalid argument"))
    76  
    77  	// Test forcing quotes.
    78  	tf.ForceQuote = true
    79  	checkQuoting(true, "")
    80  	checkQuoting(true, "abcd")
    81  	checkQuoting(true, "foo\n\rbar")
    82  	checkQuoting(true, errors.New("invalid argument"))
    83  
    84  	// Test forcing quotes when also disabling them.
    85  	tf.DisableQuote = true
    86  	checkQuoting(true, "")
    87  	checkQuoting(true, "abcd")
    88  	checkQuoting(true, "foo\n\rbar")
    89  	checkQuoting(true, errors.New("invalid argument"))
    90  
    91  	// Test disabling quotes
    92  	tf.ForceQuote = false
    93  	tf.QuoteEmptyFields = false
    94  	checkQuoting(false, "")
    95  	checkQuoting(false, "abcd")
    96  	checkQuoting(false, "foo\n\rbar")
    97  	checkQuoting(false, errors.New("invalid argument"))
    98  }
    99  
   100  func TestEscaping(t *testing.T) {
   101  	tf := &TextFormatter{DisableColors: true}
   102  
   103  	testCases := []struct {
   104  		value    string
   105  		expected string
   106  	}{
   107  		{`ba"r`, `ba\"r`},
   108  		{`ba'r`, `ba'r`},
   109  	}
   110  
   111  	for _, tc := range testCases {
   112  		b, _ := tf.Format(WithField("test", tc.value))
   113  		if !bytes.Contains(b, []byte(tc.expected)) {
   114  			t.Errorf("escaping expected for %q (result was %q instead of %q)", tc.value, string(b), tc.expected)
   115  		}
   116  	}
   117  }
   118  
   119  func TestEscaping_Interface(t *testing.T) {
   120  	tf := &TextFormatter{DisableColors: true}
   121  
   122  	ts := time.Now()
   123  
   124  	testCases := []struct {
   125  		value    interface{}
   126  		expected string
   127  	}{
   128  		{ts, fmt.Sprintf("\"%s\"", ts.String())},
   129  		{errors.New("error: something went wrong"), "\"error: something went wrong\""},
   130  	}
   131  
   132  	for _, tc := range testCases {
   133  		b, _ := tf.Format(WithField("test", tc.value))
   134  		if !bytes.Contains(b, []byte(tc.expected)) {
   135  			t.Errorf("escaping expected for %q (result was %q instead of %q)", tc.value, string(b), tc.expected)
   136  		}
   137  	}
   138  }
   139  
   140  func TestTimestampFormat(t *testing.T) {
   141  	checkTimeStr := func(format string) {
   142  		customFormatter := &TextFormatter{DisableColors: true, TimestampFormat: format}
   143  		customStr, _ := customFormatter.Format(WithField("test", "test"))
   144  		timeStart := bytes.Index(customStr, ([]byte)("time="))
   145  		timeEnd := bytes.Index(customStr, ([]byte)("level="))
   146  		timeStr := customStr[timeStart+5+len("\"") : timeEnd-1-len("\"")]
   147  		if format == "" {
   148  			format = time.RFC3339
   149  		}
   150  		_, e := time.Parse(format, (string)(timeStr))
   151  		if e != nil {
   152  			t.Errorf("time string \"%s\" did not match provided time format \"%s\": %s", timeStr, format, e)
   153  		}
   154  	}
   155  
   156  	checkTimeStr("2006-01-02T15:04:05.000000000Z07:00")
   157  	checkTimeStr("Mon Jan _2 15:04:05 2006")
   158  	checkTimeStr("")
   159  }
   160  
   161  func TestDisableLevelTruncation(t *testing.T) {
   162  	entry := &Entry{
   163  		Time:    time.Now(),
   164  		Message: "testing",
   165  	}
   166  	keys := []string{}
   167  	timestampFormat := "Mon Jan 2 15:04:05 -0700 MST 2006"
   168  	checkDisableTruncation := func(disabled bool, level Level) {
   169  		tf := &TextFormatter{DisableLevelTruncation: disabled}
   170  		var b bytes.Buffer
   171  		entry.Level = level
   172  		tf.printColored(&b, entry, keys, nil, timestampFormat)
   173  		logLine := (&b).String()
   174  		if disabled {
   175  			expected := strings.ToUpper(level.String())
   176  			if !strings.Contains(logLine, expected) {
   177  				t.Errorf("level string expected to be %s when truncation disabled", expected)
   178  			}
   179  		} else {
   180  			expected := strings.ToUpper(level.String())
   181  			if len(level.String()) > 4 {
   182  				if strings.Contains(logLine, expected) {
   183  					t.Errorf("level string %s expected to be truncated to %s when truncation is enabled", expected, expected[0:4])
   184  				}
   185  			} else {
   186  				if !strings.Contains(logLine, expected) {
   187  					t.Errorf("level string expected to be %s when truncation is enabled and level string is below truncation threshold", expected)
   188  				}
   189  			}
   190  		}
   191  	}
   192  
   193  	checkDisableTruncation(true, DebugLevel)
   194  	checkDisableTruncation(true, InfoLevel)
   195  	checkDisableTruncation(false, ErrorLevel)
   196  	checkDisableTruncation(false, InfoLevel)
   197  }
   198  
   199  func TestPadLevelText(t *testing.T) {
   200  	// A note for future maintainers / committers:
   201  	//
   202  	// This test denormalizes the level text as a part of its assertions.
   203  	// Because of that, its not really a "unit test" of the PadLevelText functionality.
   204  	// So! Many apologies to the potential future person who has to rewrite this test
   205  	// when they are changing some completely unrelated functionality.
   206  	params := []struct {
   207  		name            string
   208  		level           Level
   209  		paddedLevelText string
   210  	}{
   211  		{
   212  			name:            "PanicLevel",
   213  			level:           PanicLevel,
   214  			paddedLevelText: "PANIC  ", // 2 extra spaces
   215  		},
   216  		{
   217  			name:            "FatalLevel",
   218  			level:           FatalLevel,
   219  			paddedLevelText: "FATAL  ", // 2 extra spaces
   220  		},
   221  		{
   222  			name:            "ErrorLevel",
   223  			level:           ErrorLevel,
   224  			paddedLevelText: "ERROR  ", // 2 extra spaces
   225  		},
   226  		{
   227  			name:  "WarnLevel",
   228  			level: WarnLevel,
   229  			// WARNING is already the max length, so we don't need to assert a paddedLevelText
   230  		},
   231  		{
   232  			name:            "DebugLevel",
   233  			level:           DebugLevel,
   234  			paddedLevelText: "DEBUG  ", // 2 extra spaces
   235  		},
   236  		{
   237  			name:            "TraceLevel",
   238  			level:           TraceLevel,
   239  			paddedLevelText: "TRACE  ", // 2 extra spaces
   240  		},
   241  		{
   242  			name:            "InfoLevel",
   243  			level:           InfoLevel,
   244  			paddedLevelText: "INFO   ", // 3 extra spaces
   245  		},
   246  	}
   247  
   248  	// We create a "default" TextFormatter to do a control test.
   249  	// We also create a TextFormatter with PadLevelText, which is the parameter we want to do our most relevant assertions against.
   250  	tfDefault := TextFormatter{}
   251  	tfWithPadding := TextFormatter{PadLevelText: true}
   252  
   253  	for _, val := range params {
   254  		t.Run(val.name, func(t *testing.T) {
   255  			// TextFormatter writes into these bytes.Buffers, and we make assertions about their contents later
   256  			var bytesDefault bytes.Buffer
   257  			var bytesWithPadding bytes.Buffer
   258  
   259  			// The TextFormatter instance and the bytes.Buffer instance are different here
   260  			// all the other arguments are the same. We also initialize them so that they
   261  			// fill in the value of levelTextMaxLength.
   262  			tfDefault.init(&Entry{})
   263  			tfDefault.printColored(&bytesDefault, &Entry{Level: val.level}, []string{}, nil, "")
   264  			tfWithPadding.init(&Entry{})
   265  			tfWithPadding.printColored(&bytesWithPadding, &Entry{Level: val.level}, []string{}, nil, "")
   266  
   267  			// turn the bytes back into a string so that we can actually work with the data
   268  			logLineDefault := (&bytesDefault).String()
   269  			logLineWithPadding := (&bytesWithPadding).String()
   270  
   271  			// Control: the level text should not be padded by default
   272  			if val.paddedLevelText != "" && strings.Contains(logLineDefault, val.paddedLevelText) {
   273  				t.Errorf("log line %q should not contain the padded level text %q by default", logLineDefault, val.paddedLevelText)
   274  			}
   275  
   276  			// Assertion: the level text should still contain the string representation of the level
   277  			if !strings.Contains(strings.ToLower(logLineWithPadding), val.level.String()) {
   278  				t.Errorf("log line %q should contain the level text %q when padding is enabled", logLineWithPadding, val.level.String())
   279  			}
   280  
   281  			// Assertion: the level text should be in its padded form now
   282  			if val.paddedLevelText != "" && !strings.Contains(logLineWithPadding, val.paddedLevelText) {
   283  				t.Errorf("log line %q should contain the padded level text %q when padding is enabled", logLineWithPadding, val.paddedLevelText)
   284  			}
   285  
   286  		})
   287  	}
   288  }
   289  
   290  func TestDisableTimestampWithColoredOutput(t *testing.T) {
   291  	tf := &TextFormatter{DisableTimestamp: true, ForceColors: true}
   292  
   293  	b, _ := tf.Format(WithField("test", "test"))
   294  	if strings.Contains(string(b), "[0000]") {
   295  		t.Error("timestamp not expected when DisableTimestamp is true")
   296  	}
   297  }
   298  
   299  func TestNewlineBehavior(t *testing.T) {
   300  	tf := &TextFormatter{ForceColors: true}
   301  
   302  	// Ensure a single new line is removed as per stdlib log
   303  	e := NewEntry(StandardLogger())
   304  	e.Message = "test message\n"
   305  	b, _ := tf.Format(e)
   306  	if bytes.Contains(b, []byte("test message\n")) {
   307  		t.Error("first newline at end of Entry.Message resulted in unexpected 2 newlines in output. Expected newline to be removed.")
   308  	}
   309  
   310  	// Ensure a double new line is reduced to a single new line
   311  	e = NewEntry(StandardLogger())
   312  	e.Message = "test message\n\n"
   313  	b, _ = tf.Format(e)
   314  	if bytes.Contains(b, []byte("test message\n\n")) {
   315  		t.Error("Double newline at end of Entry.Message resulted in unexpected 2 newlines in output. Expected single newline")
   316  	}
   317  	if !bytes.Contains(b, []byte("test message\n")) {
   318  		t.Error("Double newline at end of Entry.Message did not result in a single newline after formatting")
   319  	}
   320  }
   321  
   322  func TestTextFormatterFieldMap(t *testing.T) {
   323  	formatter := &TextFormatter{
   324  		DisableColors: true,
   325  		FieldMap: FieldMap{
   326  			FieldKeyMsg:   "message",
   327  			FieldKeyLevel: "somelevel",
   328  			FieldKeyTime:  "timeywimey",
   329  		},
   330  	}
   331  
   332  	entry := &Entry{
   333  		Message: "oh hi",
   334  		Level:   WarnLevel,
   335  		Time:    time.Date(1981, time.February, 24, 4, 28, 3, 100, time.UTC),
   336  		Data: Fields{
   337  			"field1":     "f1",
   338  			"message":    "messagefield",
   339  			"somelevel":  "levelfield",
   340  			"timeywimey": "timeywimeyfield",
   341  		},
   342  	}
   343  
   344  	b, err := formatter.Format(entry)
   345  	if err != nil {
   346  		t.Fatal("Unable to format entry: ", err)
   347  	}
   348  
   349  	assert.Equal(t,
   350  		`timeywimey="1981-02-24T04:28:03Z" `+
   351  			`somelevel=warning `+
   352  			`message="oh hi" `+
   353  			`field1=f1 `+
   354  			`fields.message=messagefield `+
   355  			`fields.somelevel=levelfield `+
   356  			`fields.timeywimey=timeywimeyfield`+"\n",
   357  		string(b),
   358  		"Formatted output doesn't respect FieldMap")
   359  }
   360  
   361  func TestTextFormatterIsColored(t *testing.T) {
   362  	params := []struct {
   363  		name               string
   364  		expectedResult     bool
   365  		isTerminal         bool
   366  		disableColor       bool
   367  		forceColor         bool
   368  		envColor           bool
   369  		clicolorIsSet      bool
   370  		clicolorForceIsSet bool
   371  		clicolorVal        string
   372  		clicolorForceVal   string
   373  	}{
   374  		// Default values
   375  		{
   376  			name:               "testcase1",
   377  			expectedResult:     false,
   378  			isTerminal:         false,
   379  			disableColor:       false,
   380  			forceColor:         false,
   381  			envColor:           false,
   382  			clicolorIsSet:      false,
   383  			clicolorForceIsSet: false,
   384  		},
   385  		// Output on terminal
   386  		{
   387  			name:               "testcase2",
   388  			expectedResult:     true,
   389  			isTerminal:         true,
   390  			disableColor:       false,
   391  			forceColor:         false,
   392  			envColor:           false,
   393  			clicolorIsSet:      false,
   394  			clicolorForceIsSet: false,
   395  		},
   396  		// Output on terminal with color disabled
   397  		{
   398  			name:               "testcase3",
   399  			expectedResult:     false,
   400  			isTerminal:         true,
   401  			disableColor:       true,
   402  			forceColor:         false,
   403  			envColor:           false,
   404  			clicolorIsSet:      false,
   405  			clicolorForceIsSet: false,
   406  		},
   407  		// Output not on terminal with color disabled
   408  		{
   409  			name:               "testcase4",
   410  			expectedResult:     false,
   411  			isTerminal:         false,
   412  			disableColor:       true,
   413  			forceColor:         false,
   414  			envColor:           false,
   415  			clicolorIsSet:      false,
   416  			clicolorForceIsSet: false,
   417  		},
   418  		// Output not on terminal with color forced
   419  		{
   420  			name:               "testcase5",
   421  			expectedResult:     true,
   422  			isTerminal:         false,
   423  			disableColor:       false,
   424  			forceColor:         true,
   425  			envColor:           false,
   426  			clicolorIsSet:      false,
   427  			clicolorForceIsSet: false,
   428  		},
   429  		// Output on terminal with clicolor set to "0"
   430  		{
   431  			name:               "testcase6",
   432  			expectedResult:     false,
   433  			isTerminal:         true,
   434  			disableColor:       false,
   435  			forceColor:         false,
   436  			envColor:           true,
   437  			clicolorIsSet:      true,
   438  			clicolorForceIsSet: false,
   439  			clicolorVal:        "0",
   440  		},
   441  		// Output on terminal with clicolor set to "1"
   442  		{
   443  			name:               "testcase7",
   444  			expectedResult:     true,
   445  			isTerminal:         true,
   446  			disableColor:       false,
   447  			forceColor:         false,
   448  			envColor:           true,
   449  			clicolorIsSet:      true,
   450  			clicolorForceIsSet: false,
   451  			clicolorVal:        "1",
   452  		},
   453  		// Output not on terminal with clicolor set to "0"
   454  		{
   455  			name:               "testcase8",
   456  			expectedResult:     false,
   457  			isTerminal:         false,
   458  			disableColor:       false,
   459  			forceColor:         false,
   460  			envColor:           true,
   461  			clicolorIsSet:      true,
   462  			clicolorForceIsSet: false,
   463  			clicolorVal:        "0",
   464  		},
   465  		// Output not on terminal with clicolor set to "1"
   466  		{
   467  			name:               "testcase9",
   468  			expectedResult:     false,
   469  			isTerminal:         false,
   470  			disableColor:       false,
   471  			forceColor:         false,
   472  			envColor:           true,
   473  			clicolorIsSet:      true,
   474  			clicolorForceIsSet: false,
   475  			clicolorVal:        "1",
   476  		},
   477  		// Output not on terminal with clicolor set to "1" and force color
   478  		{
   479  			name:               "testcase10",
   480  			expectedResult:     true,
   481  			isTerminal:         false,
   482  			disableColor:       false,
   483  			forceColor:         true,
   484  			envColor:           true,
   485  			clicolorIsSet:      true,
   486  			clicolorForceIsSet: false,
   487  			clicolorVal:        "1",
   488  		},
   489  		// Output not on terminal with clicolor set to "0" and force color
   490  		{
   491  			name:               "testcase11",
   492  			expectedResult:     false,
   493  			isTerminal:         false,
   494  			disableColor:       false,
   495  			forceColor:         true,
   496  			envColor:           true,
   497  			clicolorIsSet:      true,
   498  			clicolorForceIsSet: false,
   499  			clicolorVal:        "0",
   500  		},
   501  		// Output not on terminal with clicolor_force set to "1"
   502  		{
   503  			name:               "testcase12",
   504  			expectedResult:     true,
   505  			isTerminal:         false,
   506  			disableColor:       false,
   507  			forceColor:         false,
   508  			envColor:           true,
   509  			clicolorIsSet:      false,
   510  			clicolorForceIsSet: true,
   511  			clicolorForceVal:   "1",
   512  		},
   513  		// Output not on terminal with clicolor_force set to "0"
   514  		{
   515  			name:               "testcase13",
   516  			expectedResult:     false,
   517  			isTerminal:         false,
   518  			disableColor:       false,
   519  			forceColor:         false,
   520  			envColor:           true,
   521  			clicolorIsSet:      false,
   522  			clicolorForceIsSet: true,
   523  			clicolorForceVal:   "0",
   524  		},
   525  		// Output on terminal with clicolor_force set to "0"
   526  		{
   527  			name:               "testcase14",
   528  			expectedResult:     false,
   529  			isTerminal:         true,
   530  			disableColor:       false,
   531  			forceColor:         false,
   532  			envColor:           true,
   533  			clicolorIsSet:      false,
   534  			clicolorForceIsSet: true,
   535  			clicolorForceVal:   "0",
   536  		},
   537  	}
   538  
   539  	cleanenv := func() {
   540  		os.Unsetenv("CLICOLOR")
   541  		os.Unsetenv("CLICOLOR_FORCE")
   542  	}
   543  
   544  	defer cleanenv()
   545  
   546  	for _, val := range params {
   547  		t.Run("textformatter_"+val.name, func(subT *testing.T) {
   548  			tf := TextFormatter{
   549  				isTerminal:                val.isTerminal,
   550  				DisableColors:             val.disableColor,
   551  				ForceColors:               val.forceColor,
   552  				EnvironmentOverrideColors: val.envColor,
   553  			}
   554  			cleanenv()
   555  			if val.clicolorIsSet {
   556  				os.Setenv("CLICOLOR", val.clicolorVal)
   557  			}
   558  			if val.clicolorForceIsSet {
   559  				os.Setenv("CLICOLOR_FORCE", val.clicolorForceVal)
   560  			}
   561  			res := tf.isColored()
   562  			if runtime.GOOS == "windows" && !tf.ForceColors && !val.clicolorForceIsSet {
   563  				assert.Equal(subT, false, res)
   564  			} else {
   565  				assert.Equal(subT, val.expectedResult, res)
   566  			}
   567  		})
   568  	}
   569  }
   570  
   571  func TestCustomSorting(t *testing.T) {
   572  	formatter := &TextFormatter{
   573  		DisableColors: true,
   574  		SortingFunc: func(keys []string) {
   575  			sort.Slice(keys, func(i, j int) bool {
   576  				if keys[j] == "prefix" {
   577  					return false
   578  				}
   579  				if keys[i] == "prefix" {
   580  					return true
   581  				}
   582  				return strings.Compare(keys[i], keys[j]) == -1
   583  			})
   584  		},
   585  	}
   586  
   587  	entry := &Entry{
   588  		Message: "Testing custom sort function",
   589  		Time:    time.Now(),
   590  		Level:   InfoLevel,
   591  		Data: Fields{
   592  			"test":      "testvalue",
   593  			"prefix":    "the application prefix",
   594  			"blablabla": "blablabla",
   595  		},
   596  	}
   597  	b, err := formatter.Format(entry)
   598  	require.NoError(t, err)
   599  	require.True(t, strings.HasPrefix(string(b), "prefix="), "format output is %q", string(b))
   600  }
   601
View as plain text