diff --git a/logs/file.go b/logs/file.go index cea94826..588f7860 100644 --- 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 }) } diff --git a/logs/file_test.go b/logs/file_test.go index 4216a497..e7c2ca9a 100644 --- 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 { diff --git a/logs/logger.go b/logs/logger.go index 6c2dd3f9..428d3aa0 100644 --- 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 ( diff --git a/logs/logger_test.go b/logs/logger_test.go index d6b1e935..78c67737 100644 --- 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()