github.com/keakon/golog@v0.0.0-20230330091222-cac71197c18d/writer_test.go (about)

     1  package golog
     2  
     3  import (
     4  	"bytes"
     5  	"io"
     6  	"io/ioutil"
     7  	"os"
     8  	"path/filepath"
     9  	"strconv"
    10  	"strings"
    11  	"sync"
    12  	"testing"
    13  	"time"
    14  )
    15  
    16  const maxRetryCount = 10
    17  
    18  func checkFileSize(t *testing.T, path string, size int64) {
    19  	stat, err := os.Stat(path)
    20  	if err != nil {
    21  		t.Error(err)
    22  	}
    23  
    24  	if stat.Size() != size {
    25  		t.Fatalf("file size are %d bytes", stat.Size())
    26  	}
    27  }
    28  
    29  func checkFileSizeN(t *testing.T, path string, size int64) {
    30  	for i := 0; i < maxRetryCount; i++ {
    31  		time.Sleep(flushDuration)
    32  
    33  		stat, err := os.Stat(path)
    34  		if err != nil {
    35  			if i == maxRetryCount-1 {
    36  				t.Error(err)
    37  			} else {
    38  				continue
    39  			}
    40  		}
    41  
    42  		if stat.Size() != size {
    43  			if i == maxRetryCount-1 {
    44  				t.Errorf("file size are %d bytes", stat.Size())
    45  			} else {
    46  				continue
    47  			}
    48  		} else {
    49  			break
    50  		}
    51  	}
    52  }
    53  
    54  func TestMain(m *testing.M) {
    55  	SetInternalLogger(NewStderrLogger())
    56  	os.Exit(m.Run())
    57  }
    58  
    59  func TestBufferedFileWriter(t *testing.T) {
    60  	const bufferSize = 1024
    61  
    62  	path := filepath.Join(os.TempDir(), "test.log")
    63  	os.Remove(path)
    64  	w, err := NewBufferedFileWriter(path, BufferSize(bufferSize))
    65  	if err != nil {
    66  		t.Error(err)
    67  	}
    68  
    69  	f, err := os.Open(path)
    70  	if err != nil {
    71  		t.Error(err)
    72  	}
    73  	stat, err := f.Stat()
    74  	if err != nil {
    75  		t.Error(err)
    76  	}
    77  	if stat.Size() != 0 {
    78  		t.Errorf("file size are %d bytes", stat.Size())
    79  	}
    80  
    81  	n, err := w.Write([]byte("test"))
    82  	if err != nil {
    83  		t.Error(err)
    84  	}
    85  	if n != 4 {
    86  		t.Errorf("write %d bytes, expected 4", n)
    87  	}
    88  
    89  	buf := make([]byte, bufferSize*2)
    90  
    91  	for i := 0; i < maxRetryCount; i++ {
    92  		n, err = f.Read(buf)
    93  		if err != nil {
    94  			if i == maxRetryCount-1 {
    95  				t.Error(err)
    96  			} else {
    97  				time.Sleep(flushDuration)
    98  				continue
    99  			}
   100  		} else {
   101  			break
   102  		}
   103  	}
   104  	if n != 4 {
   105  		t.Errorf("read %d bytes, expected 4", n)
   106  	}
   107  	bs := string(buf[:4])
   108  	if bs != "test" {
   109  		t.Error("read bytes are " + bs)
   110  	}
   111  
   112  	for i := 0; i < bufferSize; i++ {
   113  		w.Write([]byte{'1'})
   114  	}
   115  	w.Write([]byte{'2'}) // writes over bufferSize cause flushing
   116  	n, err = f.Read(buf)
   117  	if err != nil {
   118  		t.Error(err)
   119  	}
   120  	if n != bufferSize {
   121  		t.Errorf("read %d bytes", n)
   122  	}
   123  	if buf[bufferSize-1] != '1' {
   124  		t.Errorf("last byte is %d", buf[bufferSize-1])
   125  	}
   126  	if buf[bufferSize] != 0 {
   127  		t.Errorf("next byte is %d", buf[bufferSize-1])
   128  	}
   129  
   130  	for i := 0; i < maxRetryCount; i++ {
   131  		n, err = f.Read(buf)
   132  		if err != nil {
   133  			if i == maxRetryCount-1 {
   134  				t.Error(err)
   135  			} else {
   136  				time.Sleep(flushDuration)
   137  				continue
   138  			}
   139  		} else {
   140  			break
   141  		}
   142  	}
   143  
   144  	if n != 1 {
   145  		t.Errorf("read %d bytes", n)
   146  	}
   147  	if buf[0] != '2' {
   148  		t.Errorf("first byte is %d", buf[0])
   149  	}
   150  	if buf[1] != '1' {
   151  		t.Errorf("next byte is %d", buf[1])
   152  	}
   153  
   154  	f.Close()
   155  	w.Close()
   156  }
   157  
   158  func TestRotatingFileWriter(t *testing.T) {
   159  	dir := filepath.Join(os.TempDir(), "test")
   160  	path := filepath.Join(dir, "test.log")
   161  	err := os.RemoveAll(dir)
   162  	if err != nil {
   163  		t.Error(err)
   164  	}
   165  	err = os.Mkdir(dir, 0755)
   166  	if err != nil {
   167  		t.Error(err)
   168  	}
   169  
   170  	_, err = NewRotatingFileWriter(path, 0, 2)
   171  	if err == nil {
   172  		t.Errorf("NewRotatingFileWriter with maxSize 0 is invalid")
   173  	}
   174  
   175  	_, err = NewRotatingFileWriter(path, 128, 0)
   176  	if err == nil {
   177  		t.Errorf("NewRotatingFileWriter with backupCount 0 is invalid")
   178  	}
   179  
   180  	w, err := NewRotatingFileWriter(path, 128, 2)
   181  	if err != nil {
   182  		t.Error(err)
   183  	}
   184  	stat, err := os.Stat(path)
   185  	if err != nil {
   186  		t.Error(err)
   187  	}
   188  	if stat.Size() != 0 {
   189  		t.Errorf("file size are %d bytes", stat.Size())
   190  	}
   191  
   192  	bs := []byte("0123456789")
   193  	for i := 0; i < 20; i++ {
   194  		w.Write(bs)
   195  	}
   196  
   197  	checkFileSize(t, path, 0)
   198  
   199  	checkFileSize(t, path+".1", 130)
   200  
   201  	_, err = os.Stat(path + ".2")
   202  	if !os.IsNotExist(err) {
   203  		t.Error(err)
   204  	}
   205  
   206  	checkFileSizeN(t, path, 70)
   207  
   208  	// second write
   209  	for i := 0; i < 20; i++ {
   210  		w.Write(bs)
   211  	}
   212  
   213  	checkFileSize(t, path, 0)
   214  	checkFileSize(t, path+".1", 130)
   215  	checkFileSize(t, path+".2", 130)
   216  	checkFileSizeN(t, path, 10)
   217  
   218  	bs = make([]byte, 200)
   219  	for i := 0; i < 200; i++ {
   220  		bs[i] = '1'
   221  	}
   222  	w.Write(bs)
   223  
   224  	checkFileSize(t, path, 0)
   225  	checkFileSize(t, path+".1", 210)
   226  	checkFileSize(t, path+".2", 130)
   227  	checkFileSizeN(t, path, 0)
   228  
   229  	w.Write(bs)
   230  
   231  	checkFileSize(t, path, 0)
   232  	checkFileSize(t, path+".1", 200)
   233  	checkFileSize(t, path+".2", 210)
   234  	checkFileSizeN(t, path, 0)
   235  
   236  	w.Close()
   237  }
   238  
   239  func TestTimedRotatingFileWriterByDate(t *testing.T) {
   240  	dir := filepath.Join(os.TempDir(), "test")
   241  	pathPrefix := filepath.Join(dir, "test")
   242  	err := os.RemoveAll(dir)
   243  	if err != nil {
   244  		t.Error(err)
   245  	}
   246  	err = os.Mkdir(dir, 0755)
   247  	if err != nil {
   248  		t.Error(err)
   249  	}
   250  
   251  	tm := time.Date(2018, 11, 19, 16, 12, 34, 56, time.Local)
   252  	var lock sync.RWMutex
   253  	setNowFunc(func() time.Time {
   254  		lock.RLock()
   255  		now := tm
   256  		lock.RUnlock()
   257  		return now
   258  	})
   259  	var setNow = func(now time.Time) {
   260  		lock.Lock()
   261  		tm = now
   262  		lock.Unlock()
   263  	}
   264  
   265  	oldNextRotateDuration := nextRotateDuration
   266  	nextRotateDuration = func(rotateDuration RotateDuration) time.Duration {
   267  		return flushDuration * 3
   268  	}
   269  
   270  	_, err = NewTimedRotatingFileWriter(pathPrefix, RotateByDate, 0)
   271  	if err == nil {
   272  		t.Errorf("NewTimedRotatingFileWriter with backupCount 0 is invalid")
   273  	}
   274  
   275  	w, err := NewTimedRotatingFileWriter(pathPrefix, RotateByDate, 2)
   276  	if err != nil {
   277  		t.Error(err)
   278  	}
   279  	path := pathPrefix + "-20181119.log"
   280  	checkFileSize(t, path, 0)
   281  
   282  	w.Write([]byte("123"))
   283  	checkFileSize(t, path, 0)
   284  
   285  	setNow(time.Date(2018, 11, 20, 16, 12, 34, 56, time.Local))
   286  	time.Sleep(flushDuration * 2)
   287  	checkFileSizeN(t, path, 3)
   288  
   289  	time.Sleep(flushDuration * 2)
   290  	path = pathPrefix + "-20181120.log"
   291  	checkFileSizeN(t, path, 0)
   292  
   293  	w.Write([]byte("4567"))
   294  	setNow(time.Date(2018, 11, 21, 16, 12, 34, 56, time.Local))
   295  
   296  	time.Sleep(flushDuration * 2)
   297  	checkFileSizeN(t, path, 4)
   298  
   299  	time.Sleep(flushDuration * 3)
   300  	checkFileSizeN(t, path, 4)
   301  	checkFileSizeN(t, pathPrefix+"-20181121.log", 0)
   302  
   303  	setNow(time.Date(2018, 11, 22, 16, 12, 34, 56, time.Local))
   304  	time.Sleep(flushDuration * 3)
   305  	checkFileSizeN(t, pathPrefix+"-20181121.log", 0)
   306  	_, err = os.Stat(pathPrefix + "-20181119.log")
   307  	if !os.IsNotExist(err) {
   308  		t.Error(err)
   309  	}
   310  
   311  	w.Close()
   312  	setNowFunc(time.Now)
   313  	nextRotateDuration = oldNextRotateDuration
   314  }
   315  
   316  func TestTimedRotatingFileWriterByHour(t *testing.T) {
   317  	dir := filepath.Join(os.TempDir(), "test")
   318  	pathPrefix := filepath.Join(dir, "test")
   319  	err := os.RemoveAll(dir)
   320  	if err != nil {
   321  		t.Error(err)
   322  	}
   323  	err = os.Mkdir(dir, 0755)
   324  	if err != nil {
   325  		t.Error(err)
   326  	}
   327  
   328  	tm := time.Date(2018, 11, 19, 16, 12, 34, 56, time.Local)
   329  	var lock sync.RWMutex
   330  	setNowFunc(func() time.Time {
   331  		lock.RLock()
   332  		now := tm
   333  		lock.RUnlock()
   334  		return now
   335  	})
   336  	var setNow = func(now time.Time) {
   337  		lock.Lock()
   338  		tm = now
   339  		lock.Unlock()
   340  	}
   341  
   342  	oldNextRotateDuration := nextRotateDuration
   343  	nextRotateDuration = func(rotateDuration RotateDuration) time.Duration {
   344  		return flushDuration * 3
   345  	}
   346  
   347  	w, err := NewTimedRotatingFileWriter(pathPrefix, RotateByHour, 2)
   348  	if err != nil {
   349  		t.Error(err)
   350  	}
   351  	path := pathPrefix + "-2018111916.log"
   352  	checkFileSize(t, path, 0)
   353  
   354  	w.Write([]byte("123"))
   355  	checkFileSize(t, path, 0)
   356  
   357  	setNow(time.Date(2018, 11, 19, 17, 12, 34, 56, time.Local))
   358  	time.Sleep(flushDuration * 3)
   359  	checkFileSizeN(t, path, 3)
   360  
   361  	time.Sleep(flushDuration * 3)
   362  	path = pathPrefix + "-2018111917.log"
   363  	checkFileSizeN(t, path, 0)
   364  
   365  	w.Write([]byte("4567"))
   366  	setNow(time.Date(2018, 11, 19, 18, 12, 34, 56, time.Local))
   367  	time.Sleep(flushDuration * 3)
   368  	checkFileSizeN(t, path, 4)
   369  	checkFileSizeN(t, pathPrefix+"-2018111918.log", 0)
   370  
   371  	setNow(time.Date(2018, 11, 22, 16, 12, 34, 56, time.Local))
   372  	time.Sleep(flushDuration * 3)
   373  	checkFileSizeN(t, pathPrefix+"-2018112216.log", 0)
   374  	_, err = os.Stat(pathPrefix + "-2018111916.log")
   375  	if !os.IsNotExist(err) {
   376  		t.Error(err)
   377  	}
   378  
   379  	w.Close()
   380  	setNowFunc(time.Now)
   381  	nextRotateDuration = oldNextRotateDuration
   382  }
   383  
   384  type badWriter struct{}
   385  
   386  func (w *badWriter) Write(p []byte) (n int, err error) {
   387  	return 0, io.ErrShortWrite
   388  }
   389  
   390  func (w *badWriter) Close() error {
   391  	return nil
   392  }
   393  
   394  func TestBadWriter(t *testing.T) {
   395  	path := filepath.Join(os.TempDir(), "error.log")
   396  	os.Remove(path)
   397  	w, err := NewBufferedFileWriter(path)
   398  	if err != nil {
   399  		t.Error(err)
   400  	}
   401  
   402  	newLogger := NewLoggerWithWriter(w)
   403  	oldLogger := internalLogger
   404  	SetInternalLogger(newLogger)
   405  	defer SetInternalLogger(oldLogger)
   406  
   407  	l := NewLoggerWithWriter(&badWriter{})
   408  	l.Log(InfoLevel, "", 0, "test")
   409  	l.Close()
   410  
   411  	time.Sleep(flushDuration * 2)
   412  
   413  	content, err := ioutil.ReadFile(path)
   414  	if err != nil {
   415  		t.Error(err)
   416  	}
   417  	size := len(content)
   418  	if size == 0 {
   419  		t.Error("log is empty")
   420  		return
   421  	}
   422  
   423  	if !strings.Contains(string(content), io.ErrShortWrite.Error()) {
   424  		t.Error("bad writer raised no error")
   425  		return
   426  	}
   427  }
   428  
   429  func TestNextRotateDuration(t *testing.T) {
   430  	if nextRotateDuration(RotateByDate) > time.Hour*24 {
   431  		t.Errorf("nextRotateDuration(RotateByDate) longer than 1 day")
   432  	}
   433  	if nextRotateDuration(RotateByHour) > time.Hour {
   434  		t.Errorf("nextRotateDuration(RotateByHour) longer than 1 hour")
   435  	}
   436  }
   437  
   438  func TestConcurrentFileWriter(t *testing.T) {
   439  	path := filepath.Join(os.TempDir(), "test.log")
   440  	os.Remove(path)
   441  	w, err := NewConcurrentFileWriter(path, BufferSize(1024*1024))
   442  	if err != nil {
   443  		t.Error(err)
   444  	}
   445  
   446  	f, err := os.Open(path)
   447  	if err != nil {
   448  		t.Error(err)
   449  	}
   450  	stat, err := f.Stat()
   451  	if err != nil {
   452  		t.Error(err)
   453  	}
   454  	if stat.Size() != 0 {
   455  		t.Errorf("file size are %d bytes", stat.Size())
   456  	}
   457  
   458  	n, err := w.Write([]byte("test"))
   459  	if err != nil {
   460  		t.Error(err)
   461  	}
   462  	if n != 4 {
   463  		t.Errorf("write %d bytes, expected 4", n)
   464  	}
   465  
   466  	buf := make([]byte, defaultBufferSize)
   467  	for i := 0; i < maxRetryCount; i++ {
   468  		n, err = f.Read(buf)
   469  		if err != nil {
   470  			if i == maxRetryCount-1 {
   471  				t.Error(err)
   472  			} else {
   473  				time.Sleep(flushDuration)
   474  				continue
   475  			}
   476  		} else {
   477  			break
   478  		}
   479  	}
   480  	if n != 4 {
   481  		t.Errorf("read %d bytes, expected 4", n)
   482  	}
   483  	bs := string(buf[:4])
   484  	if bs != "test" {
   485  		t.Error("read bytes are " + bs)
   486  	}
   487  
   488  	var count = w.cpuCount
   489  	if count < 4 {
   490  		count = 4
   491  	} else if count > 10 {
   492  		count = 10
   493  	}
   494  
   495  	wg := sync.WaitGroup{}
   496  	wg.Add(count)
   497  	const writeCount = 10000
   498  	var dataSize int
   499  	for i := 0; i < count; i++ {
   500  		data := []byte("test" + strconv.Itoa(i) + "\n")
   501  		dataSize = len(data)
   502  		go func() {
   503  			for j := 0; j < writeCount; j++ {
   504  				w.Write(data)
   505  			}
   506  			wg.Done()
   507  		}()
   508  	}
   509  	wg.Wait()
   510  
   511  	for i := 0; i < maxRetryCount; i++ {
   512  		time.Sleep(flushDuration)
   513  		n, err = f.Read(buf)
   514  		if err != nil {
   515  			if i == maxRetryCount-1 {
   516  				t.Error(err)
   517  			} else {
   518  				continue
   519  			}
   520  		} else {
   521  			break
   522  		}
   523  	}
   524  	if n != count*dataSize*writeCount {
   525  		t.Errorf("read %d bytes, expected %d bytes", n, count*dataSize*writeCount)
   526  	}
   527  
   528  	lines := bytes.Split(buf[:n], []byte{'\n'})
   529  	if len(lines) != count*writeCount+1 {
   530  		t.Errorf("read %d lines, expected %d lines", len(lines), count*writeCount+1)
   531  	}
   532  	if len(lines[count*writeCount]) != 0 {
   533  		t.Error("last part is not empty")
   534  	}
   535  	lines = lines[:count*writeCount]
   536  	for i, line := range lines {
   537  		if len(line) != dataSize-1 {
   538  			t.Errorf("length of line %d is %d, expected %d", i, len(line), dataSize-1)
   539  		}
   540  	}
   541  
   542  	f.Close()
   543  	w.Close()
   544  }