trpc.group/trpc-go/trpc-go@v1.0.3/log/rollwriter/roll_writer_test.go (about) 1 // 2 // 3 // Tencent is pleased to support the open source community by making tRPC available. 4 // 5 // Copyright (C) 2023 THL A29 Limited, a Tencent company. 6 // All rights reserved. 7 // 8 // If you have downloaded a copy of the tRPC source code from Tencent, 9 // please note that tRPC source code is licensed under the Apache 2.0 License, 10 // A copy of the Apache 2.0 License is included in this file. 11 // 12 // 13 14 package rollwriter 15 16 import ( 17 "errors" 18 "fmt" 19 "io/fs" 20 "log" 21 "os" 22 "os/exec" 23 "path" 24 "path/filepath" 25 "runtime" 26 "strings" 27 "sync" 28 "testing" 29 "time" 30 31 "github.com/stretchr/testify/assert" 32 "github.com/stretchr/testify/require" 33 "go.uber.org/zap" 34 "go.uber.org/zap/zapcore" 35 ) 36 37 // functional test 38 // go test -v -cover 39 // benchmark test 40 // go test -bench=. -benchtime=20s -run=Bench 41 42 const ( 43 testTimes = 100000 44 testRoutines = 256 45 ) 46 47 func TestRollWriter(t *testing.T) { 48 49 // empty file name. 50 t.Run("empty_log_name", func(t *testing.T) { 51 logDir := t.TempDir() 52 _, err := NewRollWriter("") 53 assert.Error(t, err, "NewRollWriter: invalid log path") 54 55 // print log file list. 56 printLogFiles(logDir) 57 }) 58 59 // no rolling. 60 t.Run("roll_by_default", func(t *testing.T) { 61 logDir := t.TempDir() 62 logName := "test.log" 63 w, err := NewRollWriter(filepath.Join(logDir, logName)) 64 assert.NoError(t, err, "NewRollWriter: create logger ok") 65 log.SetOutput(w) 66 for i := 0; i < testTimes; i++ { 67 log.Printf("this is a test log: %d\n", i) 68 } 69 70 // check number of rolling log files(current files + backup files). 71 time.Sleep(20 * time.Millisecond) 72 logFiles := getLogBackups(logDir, logName) 73 if len(logFiles) != 1 { 74 t.Errorf("Number of log backup files should be 1") 75 } 76 require.Nil(t, w.Close()) 77 78 // print log file list. 79 printLogFiles(logDir) 80 }) 81 82 // roll by size. 83 t.Run("roll_by_size", func(t *testing.T) { 84 logDir := t.TempDir() 85 logName := "test_size.log" 86 const ( 87 maxBackup = 2 88 maxSize = 1 89 maxAge = 1 90 ) 91 w, err := NewRollWriter(filepath.Join(logDir, logName), 92 WithMaxSize(maxSize), 93 WithMaxAge(maxAge), 94 WithMaxBackups(maxBackup), 95 ) 96 assert.NoError(t, err, "NewRollWriter: create logger ok") 97 log.SetOutput(w) 98 for i := 0; i < testTimes; i++ { 99 log.Printf("this is a test log: %d\n", i) 100 } 101 102 w.notify() 103 // check number of rolling log files. 104 var logFiles []os.FileInfo 105 require.Eventuallyf(t, 106 func() bool { 107 logFiles = getLogBackups(logDir, logName) 108 return len(logFiles) == maxBackup+1 109 }, 110 5*time.Second, 111 time.Second, 112 "Number of log files should be %d, current: %d, %+v", 113 maxBackup+1, len(logFiles), func() []string { 114 names := make([]string, 0, len(logFiles)) 115 for _, f := range logFiles { 116 names = append(names, f.Name()) 117 } 118 return names 119 }(), 120 ) 121 122 // check rolling log file size(allow to exceed a little). 123 for _, file := range logFiles { 124 if file.Size() > 1*1024*1024+1024 { 125 t.Errorf("Log file size exceeds max_size") 126 } 127 } 128 require.Nil(t, w.Close()) 129 130 // print log file list. 131 printLogFiles(logDir) 132 }) 133 134 // rolling by time. 135 t.Run("roll_by_time", func(t *testing.T) { 136 logDir := t.TempDir() 137 logName := "test_time.log" 138 const ( 139 maxBackup = 3 140 maxSize = 1 141 maxAge = 1 142 ) 143 w, err := NewRollWriter(filepath.Join(logDir, logName), 144 WithRotationTime(".%Y%m%d"), 145 WithMaxSize(maxSize), 146 WithMaxAge(maxAge), 147 WithMaxBackups(maxBackup), 148 WithCompress(true), 149 ) 150 assert.NoError(t, err, "NewRollWriter: create logger ok") 151 log.SetOutput(w) 152 for i := 0; i < testTimes; i++ { 153 log.Printf("this is a test log: %d\n", i) 154 } 155 156 w.notify() 157 // check number of rolling log files. 158 var logFiles []os.FileInfo 159 require.Eventuallyf(t, 160 func() bool { 161 logFiles = getLogBackups(logDir, logName) 162 return len(logFiles) == maxBackup+1 163 }, 164 5*time.Second, 165 time.Second, 166 "Number of log files should be %d, current: %d, %+v", 167 maxBackup+1, len(logFiles), func() []string { 168 names := make([]string, 0, len(logFiles)) 169 for _, f := range logFiles { 170 names = append(names, f.Name()) 171 } 172 return names 173 }(), 174 ) 175 176 // check rolling log file size(allow to exceed a little). 177 for _, file := range logFiles { 178 if file.Size() > 1*1024*1024+1024 { 179 t.Errorf("Log file size exceeds max_size") 180 } 181 } 182 183 // check number of compressed files. 184 compressFileNum := 0 185 for _, file := range logFiles { 186 if strings.HasSuffix(file.Name(), compressSuffix) { 187 compressFileNum++ 188 } 189 } 190 if compressFileNum != 3 { 191 t.Errorf("Number of compress log files should be 3") 192 } 193 require.Nil(t, w.Close()) 194 195 // print log file list. 196 printLogFiles(logDir) 197 }) 198 } 199 200 func TestAsyncRollWriter(t *testing.T) { 201 logDir := t.TempDir() 202 const flushThreshold = 4 * 1024 203 204 // no rolling(asynchronous mod) 205 t.Run("roll_by_default_async", func(t *testing.T) { 206 logName := "test.log" 207 w, err := NewRollWriter(filepath.Join(logDir, logName)) 208 assert.NoError(t, err, "NewRollWriter: create logger ok") 209 210 asyncWriter := NewAsyncRollWriter(w, WithLogQueueSize(10), WithWriteLogSize(1024), 211 WithWriteLogInterval(100), WithDropLog(true)) 212 log.SetOutput(asyncWriter) 213 for i := 0; i < testTimes; i++ { 214 log.Printf("this is a test log: %d\n", i) 215 } 216 217 // check number of rolling log files. 218 time.Sleep(20 * time.Millisecond) 219 logFiles := getLogBackups(logDir, logName) 220 if len(logFiles) != 1 { 221 t.Errorf("Number of log backup files should be 1") 222 } 223 require.Nil(t, asyncWriter.Close()) 224 }) 225 226 // rolling by size(asynchronous mod) 227 t.Run("roll_by_size_async", func(t *testing.T) { 228 logName := "test_size.log" 229 w, err := NewRollWriter(filepath.Join(logDir, logName), 230 WithMaxSize(1), 231 WithMaxAge(1), 232 ) 233 assert.NoError(t, err, "NewRollWriter: create logger ok") 234 235 asyncWriter := NewAsyncRollWriter(w, WithWriteLogSize(flushThreshold)) 236 log.SetOutput(asyncWriter) 237 for i := 0; i < testTimes; i++ { 238 log.Printf("this is a test log: %d\n", i) 239 } 240 241 // check number of rolling log files. 242 time.Sleep(200 * time.Millisecond) 243 logFiles := getLogBackups(logDir, logName) 244 if len(logFiles) != 5 { 245 t.Errorf("Number of log backup files should be 5") 246 } 247 248 // check rolling log file size(asynchronous mod, may exceed 4K at most) 249 for _, file := range logFiles { 250 if file.Size() > 1*1024*1024+flushThreshold*2 { 251 t.Errorf("Log file size exceeds max_size") 252 } 253 } 254 require.Nil(t, asyncWriter.Close()) 255 }) 256 257 // rolling by time(asynchronous mod) 258 t.Run("roll_by_time_async", func(t *testing.T) { 259 logName := "test_time.log" 260 w, err := NewRollWriter(filepath.Join(logDir, logName), 261 WithRotationTime(".%Y%m%d"), 262 WithMaxSize(1), 263 WithMaxAge(1), 264 WithCompress(true), 265 ) 266 assert.NoError(t, err, "NewRollWriter: create logger ok") 267 268 asyncWriter := NewAsyncRollWriter(w, WithWriteLogSize(flushThreshold)) 269 log.SetOutput(asyncWriter) 270 for i := 0; i < testTimes; i++ { 271 log.Printf("this is a test log: %d\n", i) 272 } 273 require.Nil(t, asyncWriter.Sync()) 274 275 // check number of rolling log files. 276 time.Sleep(200 * time.Millisecond) 277 logFiles := getLogBackups(logDir, logName) 278 if len(logFiles) != 5 { 279 t.Errorf("Number of log files should be 5, current: %d", len(logFiles)) 280 } 281 282 // check rolling log file size(asynchronous, may exceed 4K at most) 283 for _, file := range logFiles { 284 if file.Size() > 1*1024*1024+flushThreshold*2 { 285 t.Errorf("Log file size exceeds max_size") 286 } 287 } 288 289 // number of compressed files. 290 compressFileNum := 0 291 for _, file := range logFiles { 292 if strings.HasSuffix(file.Name(), compressSuffix) { 293 compressFileNum++ 294 } 295 } 296 if compressFileNum != 4 { 297 t.Errorf("Number of compress log files should be 4") 298 } 299 require.Nil(t, asyncWriter.Close()) 300 }) 301 302 // wait 1 second. 303 time.Sleep(1 * time.Second) 304 305 // print log file list. 306 printLogFiles(logDir) 307 } 308 309 func TestRollWriterRace(t *testing.T) { 310 logDir := t.TempDir() 311 312 writer, err := NewRollWriter( 313 filepath.Join(logDir, "test.log"), 314 WithRotationTime(".%Y%m%d"), 315 ) 316 require.Nil(t, err) 317 writer.opts.MaxSize = 1 318 319 wg := sync.WaitGroup{} 320 wg.Add(2) 321 go func() { 322 defer wg.Done() 323 for i := 0; i < 100; i++ { 324 writer.Write([]byte(fmt.Sprintf("this is a test log: 1-%d\n", i))) 325 } 326 }() 327 328 go func() { 329 defer wg.Done() 330 for i := 0; i < 100; i++ { 331 writer.Write([]byte(fmt.Sprintf("this is a test log: 2-%d\n", i))) 332 } 333 }() 334 wg.Wait() 335 336 time.Sleep(time.Second) // Wait till all the files are closed. 337 require.Nil(t, writer.Close()) 338 } 339 340 func TestAsyncRollWriterRace(t *testing.T) { 341 logDir := t.TempDir() 342 343 writer, _ := NewRollWriter( 344 filepath.Join(logDir, "test.log"), 345 WithRotationTime(".%Y%m%d"), 346 ) 347 writer.opts.MaxSize = 1 348 w := NewAsyncRollWriter(writer) 349 350 wg := sync.WaitGroup{} 351 wg.Add(2) 352 go func() { 353 defer wg.Done() 354 for i := 0; i < 100; i++ { 355 w.Write([]byte(fmt.Sprintf("this is a test log: 1-%d\n", i))) 356 } 357 }() 358 359 go func() { 360 defer wg.Done() 361 for i := 0; i < 100; i++ { 362 w.Write([]byte(fmt.Sprintf("this is a test log: 2-%d\n", i))) 363 } 364 }() 365 wg.Wait() 366 367 time.Sleep(20 * time.Millisecond) 368 require.Nil(t, w.Close()) 369 } 370 371 func TestAsyncRollWriterSyncTwice(t *testing.T) { 372 w := NewAsyncRollWriter(&noopWriteCloser{}) 373 w.Write([]byte("hello")) 374 require.Nil(t, w.Sync()) 375 require.Nil(t, w.Sync()) 376 require.Nil(t, w.Close()) 377 } 378 379 func TestAsyncRollWriterDirectWrite(t *testing.T) { 380 logSize := 1 381 w := NewAsyncRollWriter(&noopWriteCloser{}, WithWriteLogSize(logSize)) 382 _, _ = w.Write([]byte("hello")) 383 time.Sleep(time.Millisecond) 384 require.Nil(t, w.Sync()) 385 require.Nil(t, w.Sync()) 386 require.Nil(t, w.Close()) 387 } 388 389 func TestRollWriterError(t *testing.T) { 390 logDir := t.TempDir() 391 t.Run("reopen file", func(t *testing.T) { 392 r, err := NewRollWriter(path.Join(logDir, "trpc.log")) 393 require.Nil(t, err) 394 r.os = errOS{openFileErr: errAlwaysFail} 395 r.reopenFile() 396 require.Nil(t, r.Close()) 397 }) 398 t.Run("delay close and rename file", func(t *testing.T) { 399 r, err := NewRollWriter(path.Join(logDir, "trpc.log")) 400 require.Nil(t, err) 401 r.os = errOS{renameErr: errAlwaysFail} 402 f, err := os.CreateTemp(logDir, "trpc.log") 403 require.Nil(t, err) 404 r.delayCloseAndRenameFile(&closeAndRenameFile{file: f, rename: path.Join(logDir, "tmp.log")}) 405 time.Sleep(30 * time.Millisecond) 406 require.Nil(t, r.Close()) 407 }) 408 t.Run("match log file", func(t *testing.T) { 409 r, err := NewRollWriter(path.Join(logDir, "trpc.log")) 410 require.Nil(t, err) 411 r.os = errOS{statErr: errAlwaysFail} 412 _, err = r.matchLogFile("trpc.log.20230130", "trpc.log") 413 require.NotNil(t, err) 414 require.Nil(t, r.Close()) 415 }) 416 t.Run("remove files", func(t *testing.T) { 417 r, err := NewRollWriter(path.Join(logDir, "trpc.log")) 418 require.Nil(t, err) 419 r.os = errOS{removeErr: errAlwaysFail} 420 r.removeFiles([]logInfo{{time.Time{}, &noopFileInfo{}}}) 421 require.Nil(t, r.Close()) 422 }) 423 t.Run("compress file", func(t *testing.T) { 424 file := path.Join(logDir, "trpc.log") 425 r, err := NewRollWriter(file) 426 require.Nil(t, err) 427 r.os = errOS{openErr: errAlwaysFail} 428 require.NotNil(t, r.compressFile(file, "")) 429 r.os = errOS{openFileErr: errAlwaysFail} 430 f, err := os.Create(file) 431 require.Nil(t, err) 432 require.Nil(t, f.Close()) 433 require.NotNil(t, r.compressFile(file, "")) 434 require.Nil(t, r.Close()) 435 }) 436 } 437 438 type noopFileInfo struct{} 439 440 func (*noopFileInfo) Name() string { 441 return "trpc.log" 442 } 443 444 func (*noopFileInfo) IsDir() bool { 445 return false 446 } 447 448 func (*noopFileInfo) Type() os.FileMode { 449 return fs.ModeAppend 450 } 451 452 func (*noopFileInfo) Info() (os.FileInfo, error) { 453 return &noopFileInfo{}, nil 454 } 455 456 func (*noopFileInfo) Sys() interface{} { 457 return nil 458 } 459 460 func (*noopFileInfo) Size() int64 { 461 return 0 462 } 463 464 func (*noopFileInfo) Mode() os.FileMode { 465 return os.ModePerm 466 } 467 468 func (*noopFileInfo) ModTime() time.Time { 469 return time.Time{} 470 } 471 472 var errAlwaysFail = errors.New("always fail") 473 474 type errOS struct { 475 openErr error 476 openFileErr error 477 mkdirAllErr error 478 renameErr error 479 statErr error 480 removeErr error 481 } 482 483 func (o errOS) Open(name string) (*os.File, error) { 484 if o.openErr != nil { 485 return nil, o.openErr 486 } 487 return os.Open(name) 488 } 489 490 func (o errOS) OpenFile(name string, flag int, perm fs.FileMode) (*os.File, error) { 491 if o.openFileErr != nil { 492 return nil, o.openFileErr 493 } 494 return os.OpenFile(name, flag, perm) 495 } 496 497 func (o errOS) MkdirAll(path string, perm fs.FileMode) error { 498 if o.mkdirAllErr != nil { 499 return o.mkdirAllErr 500 } 501 return os.MkdirAll(path, perm) 502 } 503 504 func (o errOS) Rename(oldpath string, newpath string) error { 505 if o.renameErr != nil { 506 return o.renameErr 507 } 508 return os.Rename(oldpath, newpath) 509 } 510 511 func (o errOS) Stat(name string) (fs.FileInfo, error) { 512 if o.statErr != nil { 513 return nil, o.statErr 514 } 515 return os.Stat(name) 516 } 517 518 func (o errOS) Remove(name string) error { 519 if o.removeErr != nil { 520 return o.removeErr 521 } 522 return os.Remove(name) 523 } 524 525 type noopWriteCloser struct{} 526 527 func (*noopWriteCloser) Write(p []byte) (n int, err error) { return } 528 529 func (*noopWriteCloser) Close() (err error) { return } 530 531 // BenchmarkRollWriterBySize benchmarks RollWriter by size. 532 func BenchmarkRollWriterBySize(b *testing.B) { 533 logDir := b.TempDir() 534 535 // init RollWriter. 536 writer, _ := NewRollWriter(filepath.Join(logDir, "test.log")) 537 core := zapcore.NewCore( 538 zapcore.NewConsoleEncoder(zap.NewProductionEncoderConfig()), 539 zapcore.AddSync(writer), 540 zapcore.DebugLevel, 541 ) 542 logger := zap.New( 543 core, 544 zap.AddCaller(), 545 ) 546 547 // warm up. 548 for i := 0; i < testTimes; i++ { 549 logger.Debug(fmt.Sprint("this is a test log: ", i)) 550 } 551 552 b.SetParallelism(testRoutines / runtime.GOMAXPROCS(0)) 553 b.ResetTimer() 554 b.RunParallel(func(pb *testing.PB) { 555 for pb.Next() { 556 logger.Debug("this is a test log") 557 } 558 }) 559 } 560 561 // BenchmarkRollWriterByTime benchmarks RollWriter by time. 562 func BenchmarkRollWriterByTime(b *testing.B) { 563 logDir := b.TempDir() 564 565 // init RollWriter. 566 writer, _ := NewRollWriter( 567 filepath.Join(logDir, "test.log"), 568 WithRotationTime(".%Y%m%d"), 569 ) 570 core := zapcore.NewCore( 571 zapcore.NewConsoleEncoder(zap.NewProductionEncoderConfig()), 572 zapcore.AddSync(writer), 573 zapcore.DebugLevel, 574 ) 575 logger := zap.New( 576 core, 577 zap.AddCaller(), 578 ) 579 580 // warm up. 581 for i := 0; i < testTimes; i++ { 582 logger.Debug(fmt.Sprint("this is a test log: ", i)) 583 } 584 585 b.SetParallelism(testRoutines / runtime.GOMAXPROCS(0)) 586 b.ResetTimer() 587 b.RunParallel(func(pb *testing.PB) { 588 for pb.Next() { 589 logger.Debug("this is a test log") 590 } 591 }) 592 } 593 594 // BenchmarkAsyncRollWriterBySize benchmarks asynchronous RollWriter. 595 func BenchmarkAsyncRollWriterBySize(b *testing.B) { 596 logDir := b.TempDir() 597 598 // init RollWriter. 599 writer, _ := NewRollWriter( 600 filepath.Join(logDir, "test.log"), 601 ) 602 asyncWriter := NewAsyncRollWriter(writer) 603 core := zapcore.NewCore( 604 zapcore.NewConsoleEncoder(zap.NewProductionEncoderConfig()), 605 asyncWriter, 606 zapcore.DebugLevel, 607 ) 608 logger := zap.New( 609 core, 610 zap.AddCaller(), 611 ) 612 613 // warm up. 614 for i := 0; i < testTimes; i++ { 615 logger.Debug(fmt.Sprint("this is a test log: ", i)) 616 } 617 618 b.SetParallelism(testRoutines / runtime.GOMAXPROCS(0)) 619 b.ResetTimer() 620 b.RunParallel(func(pb *testing.PB) { 621 for pb.Next() { 622 logger.Debug("this is a test log") 623 } 624 }) 625 } 626 627 // BenchmarkAsyncRollWriterByTime benchmarks asynchronous RollWriter by time. 628 func BenchmarkAsyncRollWriterByTime(b *testing.B) { 629 logDir := b.TempDir() 630 631 // init RollWriter. 632 writer, _ := NewRollWriter( 633 filepath.Join(logDir, "test.log"), 634 WithRotationTime(".%Y%m%d"), 635 ) 636 asyncWriter := NewAsyncRollWriter(writer) 637 core := zapcore.NewCore( 638 zapcore.NewConsoleEncoder(zap.NewProductionEncoderConfig()), 639 asyncWriter, 640 zapcore.DebugLevel, 641 ) 642 logger := zap.New( 643 core, 644 zap.AddCaller(), 645 ) 646 647 // warm up. 648 for i := 0; i < testTimes; i++ { 649 logger.Debug(fmt.Sprint("this is a test log: ", i)) 650 } 651 652 b.SetParallelism(testRoutines / runtime.GOMAXPROCS(0)) 653 b.ResetTimer() 654 b.RunParallel(func(pb *testing.PB) { 655 for pb.Next() { 656 logger.Debug("this is a test log") 657 } 658 }) 659 } 660 661 func printLogFiles(logDir string) { 662 fmt.Println("================================================") 663 fmt.Printf("[%s]:\n", logDir) 664 665 entries, err := os.ReadDir(logDir) 666 if err != nil { 667 fmt.Println("get entries failed ", err) 668 } 669 for _, entry := range entries { 670 info, err := entry.Info() 671 if err != nil { 672 fmt.Println("get info failed ", err) 673 continue 674 } 675 fmt.Println("\t", info.Name(), info.Size()) 676 } 677 } 678 679 func execCommand(name string, args ...string) string { 680 fmt.Println(name, args) 681 cmd := exec.Command(name, args...) 682 output, err := cmd.Output() 683 if err != nil { 684 fmt.Printf("exec command failed, err: %v\n", err) 685 } 686 fmt.Println(string(output)) 687 688 return string(output) 689 } 690 691 func getLogBackups(logDir, prefix string) []os.FileInfo { 692 entries, err := os.ReadDir(logDir) 693 if err != nil { 694 return nil 695 } 696 697 var logFiles []os.FileInfo 698 for _, file := range entries { 699 if !strings.HasPrefix(file.Name(), prefix) { 700 continue 701 } 702 if info, err := file.Info(); err == nil { 703 logFiles = append(logFiles, info) 704 } 705 } 706 return logFiles 707 }