You can not select more than 25 topics Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.

text_formatter_test.go 16KB

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