logs_test.go 11 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549
  1. package logx
  2. import (
  3. "encoding/json"
  4. "errors"
  5. "fmt"
  6. "io"
  7. "io/ioutil"
  8. "log"
  9. "os"
  10. "runtime"
  11. "strings"
  12. "sync"
  13. "sync/atomic"
  14. "testing"
  15. "time"
  16. "github.com/stretchr/testify/assert"
  17. )
  18. var (
  19. s = []byte("Sending #11 notification (id: 1451875113812010473) in #1 connection")
  20. pool = make(chan []byte, 1)
  21. )
  22. type mockWriter struct {
  23. lock sync.Mutex
  24. builder strings.Builder
  25. }
  26. func (mw *mockWriter) Write(data []byte) (int, error) {
  27. mw.lock.Lock()
  28. defer mw.lock.Unlock()
  29. return mw.builder.Write(data)
  30. }
  31. func (mw *mockWriter) Close() error {
  32. return nil
  33. }
  34. func (mw *mockWriter) Contains(text string) bool {
  35. mw.lock.Lock()
  36. defer mw.lock.Unlock()
  37. return strings.Contains(mw.builder.String(), text)
  38. }
  39. func (mw *mockWriter) Reset() {
  40. mw.lock.Lock()
  41. defer mw.lock.Unlock()
  42. mw.builder.Reset()
  43. }
  44. func (mw *mockWriter) String() string {
  45. mw.lock.Lock()
  46. defer mw.lock.Unlock()
  47. return mw.builder.String()
  48. }
  49. func TestFileLineFileMode(t *testing.T) {
  50. writer := new(mockWriter)
  51. errorLog = writer
  52. atomic.StoreUint32(&initialized, 1)
  53. file, line := getFileLine()
  54. Error("anything")
  55. assert.True(t, writer.Contains(fmt.Sprintf("%s:%d", file, line+1)))
  56. writer.Reset()
  57. file, line = getFileLine()
  58. Errorf("anything %s", "format")
  59. assert.True(t, writer.Contains(fmt.Sprintf("%s:%d", file, line+1)))
  60. }
  61. func TestFileLineConsoleMode(t *testing.T) {
  62. writer := new(mockWriter)
  63. writeConsole = true
  64. errorLog = newLogWriter(log.New(writer, "[ERROR] ", flags))
  65. atomic.StoreUint32(&initialized, 1)
  66. file, line := getFileLine()
  67. Error("anything")
  68. assert.True(t, writer.Contains(fmt.Sprintf("%s:%d", file, line+1)))
  69. writer.Reset()
  70. file, line = getFileLine()
  71. Errorf("anything %s", "format")
  72. assert.True(t, writer.Contains(fmt.Sprintf("%s:%d", file, line+1)))
  73. }
  74. func TestStructedLogAlert(t *testing.T) {
  75. doTestStructedLog(t, levelAlert, func(writer io.WriteCloser) {
  76. errorLog = writer
  77. }, func(v ...interface{}) {
  78. Alert(fmt.Sprint(v...))
  79. })
  80. }
  81. func TestStructedLogError(t *testing.T) {
  82. doTestStructedLog(t, levelError, func(writer io.WriteCloser) {
  83. errorLog = writer
  84. }, func(v ...interface{}) {
  85. Error(v...)
  86. })
  87. }
  88. func TestStructedLogErrorf(t *testing.T) {
  89. doTestStructedLog(t, levelError, func(writer io.WriteCloser) {
  90. errorLog = writer
  91. }, func(v ...interface{}) {
  92. Errorf("%s", fmt.Sprint(v...))
  93. })
  94. }
  95. func TestStructedLogErrorv(t *testing.T) {
  96. doTestStructedLog(t, levelError, func(writer io.WriteCloser) {
  97. errorLog = writer
  98. }, func(v ...interface{}) {
  99. Errorv(fmt.Sprint(v...))
  100. })
  101. }
  102. func TestStructedLogInfo(t *testing.T) {
  103. doTestStructedLog(t, levelInfo, func(writer io.WriteCloser) {
  104. infoLog = writer
  105. }, func(v ...interface{}) {
  106. Info(v...)
  107. })
  108. }
  109. func TestStructedLogInfof(t *testing.T) {
  110. doTestStructedLog(t, levelInfo, func(writer io.WriteCloser) {
  111. infoLog = writer
  112. }, func(v ...interface{}) {
  113. Infof("%s", fmt.Sprint(v...))
  114. })
  115. }
  116. func TestStructedLogInfov(t *testing.T) {
  117. doTestStructedLog(t, levelInfo, func(writer io.WriteCloser) {
  118. infoLog = writer
  119. }, func(v ...interface{}) {
  120. Infov(fmt.Sprint(v...))
  121. })
  122. }
  123. func TestStructedLogInfoConsoleAny(t *testing.T) {
  124. doTestStructedLogConsole(t, func(writer io.WriteCloser) {
  125. infoLog = writer
  126. }, func(v ...interface{}) {
  127. old := encoding
  128. encoding = plainEncodingType
  129. defer func() {
  130. encoding = old
  131. }()
  132. Infov(v)
  133. })
  134. }
  135. func TestStructedLogInfoConsoleAnyString(t *testing.T) {
  136. doTestStructedLogConsole(t, func(writer io.WriteCloser) {
  137. infoLog = writer
  138. }, func(v ...interface{}) {
  139. old := encoding
  140. encoding = plainEncodingType
  141. defer func() {
  142. encoding = old
  143. }()
  144. Infov(fmt.Sprint(v...))
  145. })
  146. }
  147. func TestStructedLogInfoConsoleAnyError(t *testing.T) {
  148. doTestStructedLogConsole(t, func(writer io.WriteCloser) {
  149. infoLog = writer
  150. }, func(v ...interface{}) {
  151. old := encoding
  152. encoding = plainEncodingType
  153. defer func() {
  154. encoding = old
  155. }()
  156. Infov(errors.New(fmt.Sprint(v...)))
  157. })
  158. }
  159. func TestStructedLogInfoConsoleAnyStringer(t *testing.T) {
  160. doTestStructedLogConsole(t, func(writer io.WriteCloser) {
  161. infoLog = writer
  162. }, func(v ...interface{}) {
  163. old := encoding
  164. encoding = plainEncodingType
  165. defer func() {
  166. encoding = old
  167. }()
  168. Infov(ValStringer{
  169. val: fmt.Sprint(v...),
  170. })
  171. })
  172. }
  173. func TestStructedLogInfoConsoleText(t *testing.T) {
  174. doTestStructedLogConsole(t, func(writer io.WriteCloser) {
  175. infoLog = writer
  176. }, func(v ...interface{}) {
  177. old := encoding
  178. encoding = plainEncodingType
  179. defer func() {
  180. encoding = old
  181. }()
  182. Info(fmt.Sprint(v...))
  183. })
  184. }
  185. func TestStructedLogSlow(t *testing.T) {
  186. doTestStructedLog(t, levelSlow, func(writer io.WriteCloser) {
  187. slowLog = writer
  188. }, func(v ...interface{}) {
  189. Slow(v...)
  190. })
  191. }
  192. func TestStructedLogSlowf(t *testing.T) {
  193. doTestStructedLog(t, levelSlow, func(writer io.WriteCloser) {
  194. slowLog = writer
  195. }, func(v ...interface{}) {
  196. Slowf(fmt.Sprint(v...))
  197. })
  198. }
  199. func TestStructedLogSlowv(t *testing.T) {
  200. doTestStructedLog(t, levelSlow, func(writer io.WriteCloser) {
  201. slowLog = writer
  202. }, func(v ...interface{}) {
  203. Slowv(fmt.Sprint(v...))
  204. })
  205. }
  206. func TestStructedLogStat(t *testing.T) {
  207. doTestStructedLog(t, levelStat, func(writer io.WriteCloser) {
  208. statLog = writer
  209. }, func(v ...interface{}) {
  210. Stat(v...)
  211. })
  212. }
  213. func TestStructedLogStatf(t *testing.T) {
  214. doTestStructedLog(t, levelStat, func(writer io.WriteCloser) {
  215. statLog = writer
  216. }, func(v ...interface{}) {
  217. Statf(fmt.Sprint(v...))
  218. })
  219. }
  220. func TestStructedLogSevere(t *testing.T) {
  221. doTestStructedLog(t, levelSevere, func(writer io.WriteCloser) {
  222. severeLog = writer
  223. }, func(v ...interface{}) {
  224. Severe(v...)
  225. })
  226. }
  227. func TestStructedLogSeveref(t *testing.T) {
  228. doTestStructedLog(t, levelSevere, func(writer io.WriteCloser) {
  229. severeLog = writer
  230. }, func(v ...interface{}) {
  231. Severef(fmt.Sprint(v...))
  232. })
  233. }
  234. func TestStructedLogWithDuration(t *testing.T) {
  235. const message = "hello there"
  236. writer := new(mockWriter)
  237. infoLog = writer
  238. atomic.StoreUint32(&initialized, 1)
  239. WithDuration(time.Second).Info(message)
  240. var entry logEntry
  241. if err := json.Unmarshal([]byte(writer.builder.String()), &entry); err != nil {
  242. t.Error(err)
  243. }
  244. assert.Equal(t, levelInfo, entry.Level)
  245. assert.Equal(t, message, entry.Content)
  246. assert.Equal(t, "1000.0ms", entry.Duration)
  247. }
  248. func TestSetLevel(t *testing.T) {
  249. SetLevel(ErrorLevel)
  250. const message = "hello there"
  251. writer := new(mockWriter)
  252. infoLog = writer
  253. atomic.StoreUint32(&initialized, 1)
  254. Info(message)
  255. assert.Equal(t, 0, writer.builder.Len())
  256. }
  257. func TestSetLevelTwiceWithMode(t *testing.T) {
  258. testModes := []string{
  259. "mode",
  260. "console",
  261. "volumn",
  262. }
  263. for _, mode := range testModes {
  264. testSetLevelTwiceWithMode(t, mode)
  265. }
  266. }
  267. func TestSetLevelWithDuration(t *testing.T) {
  268. SetLevel(ErrorLevel)
  269. const message = "hello there"
  270. writer := new(mockWriter)
  271. infoLog = writer
  272. atomic.StoreUint32(&initialized, 1)
  273. WithDuration(time.Second).Info(message)
  274. assert.Equal(t, 0, writer.builder.Len())
  275. }
  276. func TestErrorfWithWrappedError(t *testing.T) {
  277. SetLevel(ErrorLevel)
  278. const message = "there"
  279. writer := new(mockWriter)
  280. errorLog = writer
  281. atomic.StoreUint32(&initialized, 1)
  282. Errorf("hello %w", errors.New(message))
  283. assert.True(t, strings.Contains(writer.builder.String(), "hello there"))
  284. }
  285. func TestMustNil(t *testing.T) {
  286. Must(nil)
  287. }
  288. func TestSetup(t *testing.T) {
  289. MustSetup(LogConf{
  290. ServiceName: "any",
  291. Mode: "console",
  292. })
  293. MustSetup(LogConf{
  294. ServiceName: "any",
  295. Mode: "file",
  296. Path: os.TempDir(),
  297. })
  298. MustSetup(LogConf{
  299. ServiceName: "any",
  300. Mode: "volume",
  301. Path: os.TempDir(),
  302. })
  303. assert.NotNil(t, setupWithVolume(LogConf{}))
  304. assert.NotNil(t, setupWithFiles(LogConf{}))
  305. assert.Nil(t, setupWithFiles(LogConf{
  306. ServiceName: "any",
  307. Path: os.TempDir(),
  308. Compress: true,
  309. KeepDays: 1,
  310. }))
  311. setupLogLevel(LogConf{
  312. Level: levelInfo,
  313. })
  314. setupLogLevel(LogConf{
  315. Level: levelError,
  316. })
  317. setupLogLevel(LogConf{
  318. Level: levelSevere,
  319. })
  320. _, err := createOutput("")
  321. assert.NotNil(t, err)
  322. Disable()
  323. }
  324. func TestDisable(t *testing.T) {
  325. Disable()
  326. var opt logOptions
  327. WithKeepDays(1)(&opt)
  328. WithGzip()(&opt)
  329. assert.Nil(t, Close())
  330. writeConsole = false
  331. assert.Nil(t, Close())
  332. }
  333. func TestDisableStat(t *testing.T) {
  334. DisableStat()
  335. const message = "hello there"
  336. writer := new(mockWriter)
  337. statLog = writer
  338. atomic.StoreUint32(&initialized, 1)
  339. Stat(message)
  340. assert.Equal(t, 0, writer.builder.Len())
  341. }
  342. func TestWithGzip(t *testing.T) {
  343. fn := WithGzip()
  344. var opt logOptions
  345. fn(&opt)
  346. assert.True(t, opt.gzipEnabled)
  347. }
  348. func TestWithKeepDays(t *testing.T) {
  349. fn := WithKeepDays(1)
  350. var opt logOptions
  351. fn(&opt)
  352. assert.Equal(t, 1, opt.keepDays)
  353. }
  354. func BenchmarkCopyByteSliceAppend(b *testing.B) {
  355. for i := 0; i < b.N; i++ {
  356. var buf []byte
  357. buf = append(buf, getTimestamp()...)
  358. buf = append(buf, ' ')
  359. buf = append(buf, s...)
  360. _ = buf
  361. }
  362. }
  363. func BenchmarkCopyByteSliceAllocExactly(b *testing.B) {
  364. for i := 0; i < b.N; i++ {
  365. now := []byte(getTimestamp())
  366. buf := make([]byte, len(now)+1+len(s))
  367. n := copy(buf, now)
  368. buf[n] = ' '
  369. copy(buf[n+1:], s)
  370. }
  371. }
  372. func BenchmarkCopyByteSlice(b *testing.B) {
  373. var buf []byte
  374. for i := 0; i < b.N; i++ {
  375. buf = make([]byte, len(s))
  376. copy(buf, s)
  377. }
  378. fmt.Fprint(ioutil.Discard, buf)
  379. }
  380. func BenchmarkCopyOnWriteByteSlice(b *testing.B) {
  381. var buf []byte
  382. for i := 0; i < b.N; i++ {
  383. size := len(s)
  384. buf = s[:size:size]
  385. }
  386. fmt.Fprint(ioutil.Discard, buf)
  387. }
  388. func BenchmarkCacheByteSlice(b *testing.B) {
  389. for i := 0; i < b.N; i++ {
  390. dup := fetch()
  391. copy(dup, s)
  392. put(dup)
  393. }
  394. }
  395. func BenchmarkLogs(b *testing.B) {
  396. b.ReportAllocs()
  397. log.SetOutput(ioutil.Discard)
  398. for i := 0; i < b.N; i++ {
  399. Info(i)
  400. }
  401. }
  402. func fetch() []byte {
  403. select {
  404. case b := <-pool:
  405. return b
  406. default:
  407. }
  408. return make([]byte, 4096)
  409. }
  410. func getFileLine() (string, int) {
  411. _, file, line, _ := runtime.Caller(1)
  412. short := file
  413. for i := len(file) - 1; i > 0; i-- {
  414. if file[i] == '/' {
  415. short = file[i+1:]
  416. break
  417. }
  418. }
  419. return short, line
  420. }
  421. func put(b []byte) {
  422. select {
  423. case pool <- b:
  424. default:
  425. }
  426. }
  427. func doTestStructedLog(t *testing.T, level string, setup func(writer io.WriteCloser),
  428. write func(...interface{})) {
  429. const message = "hello there"
  430. writer := new(mockWriter)
  431. setup(writer)
  432. atomic.StoreUint32(&initialized, 1)
  433. write(message)
  434. var entry logEntry
  435. if err := json.Unmarshal([]byte(writer.builder.String()), &entry); err != nil {
  436. t.Error(err)
  437. }
  438. assert.Equal(t, level, entry.Level)
  439. val, ok := entry.Content.(string)
  440. assert.True(t, ok)
  441. assert.True(t, strings.Contains(val, message))
  442. }
  443. func doTestStructedLogConsole(t *testing.T, setup func(writer io.WriteCloser),
  444. write func(...interface{})) {
  445. const message = "hello there"
  446. writer := new(mockWriter)
  447. setup(writer)
  448. atomic.StoreUint32(&initialized, 1)
  449. write(message)
  450. println(writer.String())
  451. assert.True(t, strings.Contains(writer.String(), message))
  452. }
  453. func testSetLevelTwiceWithMode(t *testing.T, mode string) {
  454. SetUp(LogConf{
  455. Mode: mode,
  456. Level: "error",
  457. Path: "/dev/null",
  458. })
  459. SetUp(LogConf{
  460. Mode: mode,
  461. Level: "info",
  462. Path: "/dev/null",
  463. })
  464. const message = "hello there"
  465. writer := new(mockWriter)
  466. infoLog = writer
  467. atomic.StoreUint32(&initialized, 1)
  468. Info(message)
  469. assert.Equal(t, 0, writer.builder.Len())
  470. Infof(message)
  471. assert.Equal(t, 0, writer.builder.Len())
  472. ErrorStack(message)
  473. assert.Equal(t, 0, writer.builder.Len())
  474. ErrorStackf(message)
  475. assert.Equal(t, 0, writer.builder.Len())
  476. }
  477. type ValStringer struct {
  478. val string
  479. }
  480. func (v ValStringer) String() string {
  481. return v.val
  482. }