Merge pull request #2986 from oxgo/hourlylog

add hourly log rotate
2018-07-30 12:26:37 +08:00 · 2018-07-30 12:26:37 +08:00 · 5051d902fb
parent 48acfa08be 046cb248e0
commit 5051d902fb
4 changed files with 222 additions and 44 deletions
--- a/logs/file.go
+++ b/logs/file.go
@ -54,6 +54,12 @@ type fileLogWriter struct {
 	dailyOpenDate int
 	dailyOpenTime time.Time

+	// Rotate hourly
+	Hourly         bool  `json:"hourly"`
+	MaxHours       int64 `json:"maxhours"`
+	hourlyOpenDate int
+	hourlyOpenTime time.Time
+
 	Rotate bool `json:"rotate"`

 	Level int `json:"level"`
@ -70,6 +76,8 @@ func newFileWriter() Logger {
 	w := &fileLogWriter{
 		Daily:      true,
 		MaxDays:    7,
+		Hourly:     false,
+		MaxHours:   168,
 		Rotate:     true,
 		RotatePerm: "0440",
 		Level:      LevelTrace,
@ -83,15 +91,15 @@ func newFileWriter() Logger {

 // Init file logger with json config.
 // jsonConfig like:
-//	{
-//	"filename":"logs/beego.log",
-//	"maxLines":10000,
-//	"maxsize":1024,
-//	"daily":true,
-//	"maxDays":15,
-//	"rotate":true,
-//  	"perm":"0600"
-//	}
+//  {
+//  "filename":"logs/beego.log",
+//  "maxLines":10000,
+//  "maxsize":1024,
+//  "daily":true,
+//  "maxDays":15,
+//  "rotate":true,
+//      "perm":"0600"
+//  }
 func (w *fileLogWriter) Init(jsonConfig string) error {
 	err := json.Unmarshal([]byte(jsonConfig), w)
 	if err != nil {
@ -122,10 +130,16 @@ func (w *fileLogWriter) startLogger() error {
 	return w.initFd()
 }

-func (w *fileLogWriter) needRotate(size int, day int) bool {
+func (w *fileLogWriter) needRotateDaily(size int, day int) bool {
 	return (w.MaxLines > 0 && w.maxLinesCurLines >= w.MaxLines) ||
 		(w.MaxSize > 0 && w.maxSizeCurSize >= w.MaxSize) ||
 		(w.Daily && day != w.dailyOpenDate)
+}
+
+func (w *fileLogWriter) needRotateHourly(size int, hour int) bool {
+	return (w.MaxLines > 0 && w.maxLinesCurLines >= w.MaxLines) ||
+		(w.MaxSize > 0 && w.maxSizeCurSize >= w.MaxSize) ||
+		(w.Hourly && hour != w.hourlyOpenDate)

 }

@ -134,14 +148,23 @@ func (w *fileLogWriter) WriteMsg(when time.Time, msg string, level int) error {
 	if level > w.Level {
 		return nil
 	}
-	h, d := formatTimeHeader(when)
-	msg = string(h) + msg + "\n"
+	hd, d, h := formatTimeHeader(when)
+	msg = string(hd) + msg + "\n"
 	if w.Rotate {
 		w.RLock()
-		if w.needRotate(len(msg), d) {
+		if w.needRotateHourly(len(msg), h) {
 			w.RUnlock()
 			w.Lock()
-			if w.needRotate(len(msg), d) {
+			if w.needRotateHourly(len(msg), h) {
+				if err := w.doRotate(when); err != nil {
+					fmt.Fprintf(os.Stderr, "FileLogWriter(%q): %s\n", w.Filename, err)
+				}
+			}
+			w.Unlock()
+		} else if w.needRotateDaily(len(msg), d) {
+			w.RUnlock()
+			w.Lock()
+			if w.needRotateDaily(len(msg), d) {
 				if err := w.doRotate(when); err != nil {
 					fmt.Fprintf(os.Stderr, "FileLogWriter(%q): %s\n", w.Filename, err)
 				}
@ -189,8 +212,12 @@ func (w *fileLogWriter) initFd() error {
 	w.maxSizeCurSize = int(fInfo.Size())
 	w.dailyOpenTime = time.Now()
 	w.dailyOpenDate = w.dailyOpenTime.Day()
+	w.hourlyOpenTime = time.Now()
+	w.hourlyOpenDate = w.hourlyOpenTime.Hour()
 	w.maxLinesCurLines = 0
-	if w.Daily {
+	if w.Hourly {
+		go w.hourlyRotate(w.hourlyOpenTime)
+	} else if w.Daily {
 		go w.dailyRotate(w.dailyOpenTime)
 	}
 	if fInfo.Size() > 0 && w.MaxLines > 0 {
@ -209,7 +236,22 @@ func (w *fileLogWriter) dailyRotate(openTime time.Time) {
 	tm := time.NewTimer(time.Duration(nextDay.UnixNano() - openTime.UnixNano() + 100))
 	<-tm.C
 	w.Lock()
-	if w.needRotate(0, time.Now().Day()) {
+	if w.needRotateDaily(0, time.Now().Day()) {
+		if err := w.doRotate(time.Now()); err != nil {
+			fmt.Fprintf(os.Stderr, "FileLogWriter(%q): %s\n", w.Filename, err)
+		}
+	}
+	w.Unlock()
+}
+
+func (w *fileLogWriter) hourlyRotate(openTime time.Time) {
+	y, m, d := openTime.Add(1 * time.Hour).Date()
+	h, _, _ := openTime.Add(1 * time.Hour).Clock()
+	nextHour := time.Date(y, m, d, h, 0, 0, 0, openTime.Location())
+	tm := time.NewTimer(time.Duration(nextHour.UnixNano() - openTime.UnixNano() + 100))
+	<-tm.C
+	w.Lock()
+	if w.needRotateHourly(0, time.Now().Hour()) {
 		if err := w.doRotate(time.Now()); err != nil {
 			fmt.Fprintf(os.Stderr, "FileLogWriter(%q): %s\n", w.Filename, err)
 		}
@ -251,6 +293,8 @@ func (w *fileLogWriter) doRotate(logTime time.Time) error {
 	// Find the next available number
 	num := w.MaxFilesCurFiles + 1
 	fName := ""
+	format := ""
+	var openTime time.Time
 	rotatePerm, err := strconv.ParseInt(w.RotatePerm, 8, 64)
 	if err != nil {
 		return err
@ -262,17 +306,26 @@ func (w *fileLogWriter) doRotate(logTime time.Time) error {
 		goto RESTART_LOGGER
 	}

+	if w.Hourly {
+		format = "2006010215"
+		openTime = w.hourlyOpenTime
+	} else if w.Daily {
+		format = "2006-01-02"
+		openTime = w.dailyOpenTime
+	}
+
 	// only when one of them be setted, then the file would be splited
 	if w.MaxLines > 0 || w.MaxSize > 0 {
 		for ; err == nil && num <= w.MaxFiles; num++ {
-			fName = w.fileNameOnly + fmt.Sprintf(".%s.%03d%s", logTime.Format("2006-01-02"), num, w.suffix)
+			fName = w.fileNameOnly + fmt.Sprintf(".%s.%03d%s", logTime.Format(format), num, w.suffix)
 			_, err = os.Lstat(fName)
 		}
 	} else {
-		fName = w.fileNameOnly + fmt.Sprintf(".%s.%03d%s", w.dailyOpenTime.Format("2006-01-02"), num, w.suffix)
+		fName = w.fileNameOnly + fmt.Sprintf(".%s.%03d%s", openTime.Format(format), num, w.suffix)
 		_, err = os.Lstat(fName)
 		w.MaxFilesCurFiles = num
 	}
+
 	// return error if the last file checked still existed
 	if err == nil {
 		return fmt.Errorf("Rotate: Cannot find free log number to rename %s", w.Filename)
@ -316,13 +369,21 @@ func (w *fileLogWriter) deleteOldLog() {
 		if info == nil {
 			return
 		}
-
-		if !info.IsDir() && info.ModTime().Add(24 * time.Hour * time.Duration(w.MaxDays)).Before(time.Now()) {
-			if strings.HasPrefix(filepath.Base(path), filepath.Base(w.fileNameOnly)) &&
-				strings.HasSuffix(filepath.Base(path), w.suffix) {
-				os.Remove(path)
-			}
-		}
+        if w.Hourly {
+            if !info.IsDir() && info.ModTime().Add(1 * time.Hour * time.Duration(w.MaxHours)).Before(time.Now()) {
+                if strings.HasPrefix(filepath.Base(path), filepath.Base(w.fileNameOnly)) &&
+                strings.HasSuffix(filepath.Base(path), w.suffix) {
+                    os.Remove(path)
+                }
+            }
+        } else if w.Daily {
+            if !info.IsDir() && info.ModTime().Add(24 * time.Hour * time.Duration(w.MaxDays)).Before(time.Now()) {
+                if strings.HasPrefix(filepath.Base(path), filepath.Base(w.fileNameOnly)) &&
+                strings.HasSuffix(filepath.Base(path), w.suffix) {
+                    os.Remove(path)
+                }
+            }
+        }
 		return
 	})
 }
--- a/logs/file_test.go
+++ b/logs/file_test.go
@ -112,7 +112,7 @@ func TestFile2(t *testing.T) {
 	os.Remove("test2.log")
 }

-func TestFileRotate_01(t *testing.T) {
+func TestFileDailyRotate_01(t *testing.T) {
 	log := NewLogger(10000)
 	log.SetLogger("file", `{"filename":"test3.log","maxlines":4}`)
 	log.Debug("debug")
@ -133,28 +133,28 @@ func TestFileRotate_01(t *testing.T) {
 	os.Remove("test3.log")
 }

-func TestFileRotate_02(t *testing.T) {
+func TestFileDailyRotate_02(t *testing.T) {
 	fn1 := "rotate_day.log"
 	fn2 := "rotate_day." + time.Now().Add(-24*time.Hour).Format("2006-01-02") + ".001.log"
-	testFileRotate(t, fn1, fn2)
+	testFileRotate(t, fn1, fn2, true, false)
 }

-func TestFileRotate_03(t *testing.T) {
+func TestFileDailyRotate_03(t *testing.T) {
 	fn1 := "rotate_day.log"
 	fn := "rotate_day." + time.Now().Add(-24*time.Hour).Format("2006-01-02") + ".log"
 	os.Create(fn)
 	fn2 := "rotate_day." + time.Now().Add(-24*time.Hour).Format("2006-01-02") + ".001.log"
-	testFileRotate(t, fn1, fn2)
+	testFileRotate(t, fn1, fn2, true, false)
 	os.Remove(fn)
 }

-func TestFileRotate_04(t *testing.T) {
+func TestFileDailyRotate_04(t *testing.T) {
 	fn1 := "rotate_day.log"
 	fn2 := "rotate_day." + time.Now().Add(-24*time.Hour).Format("2006-01-02") + ".001.log"
 	testFileDailyRotate(t, fn1, fn2)
 }

-func TestFileRotate_05(t *testing.T) {
+func TestFileDailyRotate_05(t *testing.T) {
 	fn1 := "rotate_day.log"
 	fn := "rotate_day." + time.Now().Add(-24*time.Hour).Format("2006-01-02") + ".log"
 	os.Create(fn)
@ -162,7 +162,7 @@ func TestFileRotate_05(t *testing.T) {
 	testFileDailyRotate(t, fn1, fn2)
 	os.Remove(fn)
 }
-func TestFileRotate_06(t *testing.T) { //test file mode
+func TestFileDailyRotate_06(t *testing.T) { //test file mode
 	log := NewLogger(10000)
 	log.SetLogger("file", `{"filename":"test3.log","maxlines":4}`)
 	log.Debug("debug")
@ -183,19 +183,105 @@ func TestFileRotate_06(t *testing.T) { //test file mode
 	os.Remove(rotateName)
 	os.Remove("test3.log")
 }
-func testFileRotate(t *testing.T, fn1, fn2 string) {
+
+func TestFileHourlyRotate_01(t *testing.T) {
+	log := NewLogger(10000)
+    log.SetLogger("file", `{"filename":"test3.log","hourly":true,"maxlines":4}`)
+	log.Debug("debug")
+	log.Info("info")
+	log.Notice("notice")
+	log.Warning("warning")
+	log.Error("error")
+	log.Alert("alert")
+	log.Critical("critical")
+	log.Emergency("emergency")
+	rotateName := "test3" + fmt.Sprintf(".%s.%03d", time.Now().Format("2006010215"), 1) + ".log"
+	b, err := exists(rotateName)
+	if !b || err != nil {
+		os.Remove("test3.log")
+		t.Fatal("rotate not generated")
+	}
+	os.Remove(rotateName)
+	os.Remove("test3.log")
+}
+
+func TestFileHourlyRotate_02(t *testing.T) {
+	fn1 := "rotate_hour.log"
+	fn2 := "rotate_hour." + time.Now().Add(-1*time.Hour).Format("2006010215") + ".001.log"
+	testFileRotate(t, fn1, fn2, false, true)
+}
+
+func TestFileHourlyRotate_03(t *testing.T) {
+	fn1 := "rotate_hour.log"
+	fn := "rotate_hour." + time.Now().Add(-1*time.Hour).Format("2006010215") + ".log"
+	os.Create(fn)
+	fn2 := "rotate_hour." + time.Now().Add(-1*time.Hour).Format("2006010215") + ".001.log"
+	testFileRotate(t, fn1, fn2, false, true)
+	os.Remove(fn)
+}
+
+func TestFileHourlyRotate_04(t *testing.T) {
+	fn1 := "rotate_hour.log"
+	fn2 := "rotate_hour." + time.Now().Add(-1*time.Hour).Format("2006010215") + ".001.log"
+	testFileHourlyRotate(t, fn1, fn2)
+}
+
+func TestFileHourlyRotate_05(t *testing.T) {
+	fn1 := "rotate_hour.log"
+	fn := "rotate_hour." + time.Now().Add(-1*time.Hour).Format("2006010215") + ".log"
+	os.Create(fn)
+	fn2 := "rotate_hour." + time.Now().Add(-1*time.Hour).Format("2006010215") + ".001.log"
+	testFileHourlyRotate(t, fn1, fn2)
+	os.Remove(fn)
+}
+
+func TestFileHourlyRotate_06(t *testing.T) { //test file mode
+	log := NewLogger(10000)
+    log.SetLogger("file", `{"filename":"test3.log", "hourly":true, "maxlines":4}`)
+	log.Debug("debug")
+	log.Info("info")
+	log.Notice("notice")
+	log.Warning("warning")
+	log.Error("error")
+	log.Alert("alert")
+	log.Critical("critical")
+	log.Emergency("emergency")
+	rotateName := "test3" + fmt.Sprintf(".%s.%03d", time.Now().Format("2006010215"), 1) + ".log"
+	s, _ := os.Lstat(rotateName)
+	if s.Mode() != 0440 {
+		os.Remove(rotateName)
+		os.Remove("test3.log")
+		t.Fatal("rotate file mode error")
+	}
+	os.Remove(rotateName)
+	os.Remove("test3.log")
+}
+
+func testFileRotate(t *testing.T, fn1, fn2 string, daily, hourly bool) {
 	fw := &fileLogWriter{
-		Daily:      true,
+		Daily:      daily,
 		MaxDays:    7,
+		Hourly:     hourly,
+		MaxHours:   168,
 		Rotate:     true,
 		Level:      LevelTrace,
 		Perm:       "0660",
 		RotatePerm: "0440",
 	}
-	fw.Init(fmt.Sprintf(`{"filename":"%v","maxdays":1}`, fn1))
-	fw.dailyOpenTime = time.Now().Add(-24 * time.Hour)
-	fw.dailyOpenDate = fw.dailyOpenTime.Day()
-	fw.WriteMsg(time.Now(), "this is a msg for test", LevelDebug)
+
+    if daily {
+        fw.Init(fmt.Sprintf(`{"filename":"%v","maxdays":1}`, fn1))
+        fw.dailyOpenTime = time.Now().Add(-24 * time.Hour)
+        fw.dailyOpenDate = fw.dailyOpenTime.Day()
+    }
+
+    if hourly {
+        fw.Init(fmt.Sprintf(`{"filename":"%v","maxhours":1}`, fn1))
+        fw.hourlyOpenTime = time.Now().Add(-1 * time.Hour)
+        fw.hourlyOpenDate = fw.hourlyOpenTime.Day()
+    }
+
+    fw.WriteMsg(time.Now(), "this is a msg for test", LevelDebug)

 	for _, file := range []string{fn1, fn2} {
 		_, err := os.Stat(file)
@ -240,6 +326,37 @@ func testFileDailyRotate(t *testing.T, fn1, fn2 string) {
 	fw.Destroy()
 }

+func testFileHourlyRotate(t *testing.T, fn1, fn2 string) {
+	fw := &fileLogWriter{
+        Hourly:      true,
+        MaxHours:    168,
+		Rotate:     true,
+		Level:      LevelTrace,
+		Perm:       "0660",
+		RotatePerm: "0440",
+	}
+	fw.Init(fmt.Sprintf(`{"filename":"%v","maxhours":1}`, fn1))
+	fw.hourlyOpenTime = time.Now().Add(-1 * time.Hour)
+	fw.hourlyOpenDate = fw.hourlyOpenTime.Hour()
+	hour, _ := time.ParseInLocation("2006010215", time.Now().Format("2006010215"), fw.hourlyOpenTime.Location())
+	hour = hour.Add(-1 * time.Second)
+	fw.hourlyRotate(hour)
+	for _, file := range []string{fn1, fn2} {
+		_, err := os.Stat(file)
+		if err != nil {
+			t.FailNow()
+		}
+		content, err := ioutil.ReadFile(file)
+		if err != nil {
+			t.FailNow()
+		}
+		if len(content) > 0 {
+			t.FailNow()
+		}
+		os.Remove(file)
+	}
+	fw.Destroy()
+}
 func exists(path string) (bool, error) {
 	_, err := os.Stat(path)
 	if err == nil {
--- a/logs/logger.go
+++ b/logs/logger.go
@ -33,7 +33,7 @@ func newLogWriter(wr io.Writer) *logWriter {

 func (lg *logWriter) println(when time.Time, msg string) {
 	lg.Lock()
-	h, _ := formatTimeHeader(when)
+	h, _, _:= formatTimeHeader(when)
 	lg.writer.Write(append(append(h, msg...), '\n'))
 	lg.Unlock()
 }
@ -90,7 +90,7 @@ const (
 	ns1 = `0123456789`
 )

-func formatTimeHeader(when time.Time) ([]byte, int) {
+func formatTimeHeader(when time.Time) ([]byte, int, int) {
 	y, mo, d := when.Date()
 	h, mi, s := when.Clock()
 	ns := when.Nanosecond() / 1000000
@ -123,7 +123,7 @@ func formatTimeHeader(when time.Time) ([]byte, int) {

 	buf[23] = ' '

-	return buf[0:], d
+	return buf[0:], d, h
 }

 var (
--- a/logs/logger_test.go
+++ b/logs/logger_test.go
@ -30,7 +30,7 @@ func TestFormatHeader_0(t *testing.T) {
 		if tm.Year() >= 2100 {
 			break
 		}
-		h, _ := formatTimeHeader(tm)
+		h, _, _ := formatTimeHeader(tm)
 		if tm.Format("2006/01/02 15:04:05.000 ") != string(h) {
 			t.Log(tm)
 			t.FailNow()
@ -48,7 +48,7 @@ func TestFormatHeader_1(t *testing.T) {
 		if tm.Year() >= year+1 {
 			break
 		}
-		h, _ := formatTimeHeader(tm)
+		h, _, _ := formatTimeHeader(tm)
 		if tm.Format("2006/01/02 15:04:05.000 ") != string(h) {
 			t.Log(tm)
 			t.FailNow()