diff --git a/logs/console_test.go b/logs/console_test.go index 2fad7241..c4bb1da2 100644 --- a/logs/console_test.go +++ b/logs/console_test.go @@ -43,11 +43,3 @@ func TestConsole(t *testing.T) { testConsoleCalls(log2) } -func BenchmarkConsole(b *testing.B) { - log := NewLogger(10000) - log.EnableFuncCallDepth(true) - log.SetLogger("console", "") - for i := 0; i < b.N; i++ { - log.Debug("debug") - } -} diff --git a/logs/file.go b/logs/file.go index 9596258c..0eae734a 100644 --- a/logs/file.go +++ b/logs/file.go @@ -20,7 +20,6 @@ import ( "errors" "fmt" "io" - "log" "os" "path/filepath" "strings" @@ -31,85 +30,59 @@ import ( // fileLogWriter implements LoggerInterface. // It writes messages by lines limit, file size limit, or time frequency. type fileLogWriter struct { - *log.Logger - mw *MuxWriter + sync.Mutex // write log order by order and atomic incr maxLinesCurLines and maxSizeCurSize // The opened file - Filename string `json:"filename"` + Filename string `json:"filename"` + fileWriter *os.File - Maxlines int `json:"maxlines"` - maxlinesCurlines int + // Rotate at line + MaxLines int `json:"maxlines"` + maxLinesCurLines int // Rotate at size - Maxsize int `json:"maxsize"` - maxsizeCursize int + MaxSize int `json:"maxsize"` + maxSizeCurSize int // Rotate daily Daily bool `json:"daily"` - Maxdays int64 `json:"maxdays"` - dailyOpendate int + MaxDays int64 `json:"maxdays"` + dailyOpenDate int Rotate bool `json:"rotate"` - startLock sync.Mutex // Only one log can write to the file - Level int `json:"level"` Perm os.FileMode `json:"perm"` } -// MuxWriter is an *os.File writer with locker. -type MuxWriter struct { - sync.Mutex - fd *os.File -} - -// write to os.File. -func (l *MuxWriter) Write(b []byte) (int, error) { - l.Lock() - defer l.Unlock() - return l.fd.Write(b) -} - -// SetFd set os.File in writer. -func (l *MuxWriter) SetFd(fd *os.File) { - if l.fd != nil { - l.fd.Close() - } - l.fd = fd -} - // NewFileWriter create a FileLogWriter returning as LoggerInterface. func newFileWriter() Logger { w := &fileLogWriter{ Filename: "", - Maxlines: 1000000, - Maxsize: 1 << 28, //256 MB + MaxLines: 1000000, + MaxSize: 1 << 28, //256 MB Daily: true, - Maxdays: 7, + MaxDays: 7, Rotate: true, Level: LevelTrace, Perm: 0660, } - // use MuxWriter instead direct use os.File for lock write when rotate - w.mw = new(MuxWriter) - // set MuxWriter as Logger's io.Writer - w.Logger = log.New(w.mw, "", log.Ldate|log.Ltime) return w } // Init file logger with json config. -// jsonconfig like: +// jsonConfig like: // { // "filename":"logs/beego.log", -// "maxlines":10000, +// "maxLines":10000, // "maxsize":1<<30, // "daily":true, -// "maxdays":15, +// "maxDays":15, // "rotate":true, -// "perm":0600 +// "perm":0600 // } -func (w *fileLogWriter) Init(jsonconfig string) error { - err := json.Unmarshal([]byte(jsonconfig), w) +func (w *fileLogWriter) Init(jsonConfig string) error { + err := json.Unmarshal([]byte(jsonConfig), w) if err != nil { return err } @@ -122,27 +95,22 @@ func (w *fileLogWriter) Init(jsonconfig string) error { // start file logger. create log file and set to locker-inside file writer. func (w *fileLogWriter) startLogger() error { - fd, err := w.createLogFile() + file, err := w.createLogFile() if err != nil { return err } - w.mw.SetFd(fd) + if w.fileWriter != nil { + w.fileWriter.Close() + } + w.fileWriter = file return w.initFd() } -func (w *fileLogWriter) docheck(size int) { - w.startLock.Lock() - defer w.startLock.Unlock() - if w.Rotate && ((w.Maxlines > 0 && w.maxlinesCurlines >= w.Maxlines) || - (w.Maxsize > 0 && w.maxsizeCursize >= w.Maxsize) || - (w.Daily && time.Now().Day() != w.dailyOpendate)) { - if err := w.DoRotate(); err != nil { - fmt.Fprintf(os.Stderr, "FileLogWriter(%q): %s\n", w.Filename, err) - return - } - } - w.maxlinesCurlines++ - w.maxsizeCursize += size +func (w *fileLogWriter) needRotate(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) + } // WriteMsg write logger message into file. @@ -150,10 +118,68 @@ func (w *fileLogWriter) WriteMsg(msg string, level int) error { if level > w.Level { return nil } - n := 24 + len(msg) // 24 stand for the length "2013/06/23 21:00:22 [T] " - w.docheck(n) - w.Logger.Println(msg) - return nil + //2016/01/12 21:34:33 + now := time.Now() + y, mo, d := now.Date() + h, mi, s := now.Clock() + //len(2006/01/02 15:03:04)==19 + var buf [20]byte + t := 3 + for y >= 10 { + p := y / 10 + buf[t] = byte('0' + y - p*10) + y = p + t-- + } + buf[0] = byte('0' + y) + buf[4] = '/' + if mo > 9 { + buf[5] = '1' + buf[6] = byte('0' + mo - 9) + } else { + buf[5] = '0' + buf[6] = byte('0' + mo) + } + buf[7] = '/' + t = d / 10 + buf[8] = byte('0' + t) + buf[9] = byte('0' + d - t*10) + buf[10] = ' ' + t = h / 10 + buf[11] = byte('0' + t) + buf[12] = byte('0' + h - t*10) + buf[13] = ':' + t = mi / 10 + buf[14] = byte('0' + t) + buf[15] = byte('0' + mi - t*10) + buf[16] = ':' + t = s / 10 + buf[17] = byte('0' + t) + buf[18] = byte('0' + s - t*10) + buf[19] = ' ' + msg = string(buf[0:]) + msg + "\n" + + if w.Rotate { + if w.needRotate(len(msg), d) { + w.Lock() + if w.needRotate(len(msg), d) { + if err := w.doRotate(); err != nil { + fmt.Fprintf(os.Stderr, "FileLogWriter(%q): %s\n", w.Filename, err) + } + + } + w.Unlock() + } + } + + w.Lock() + _, err := w.fileWriter.Write([]byte(msg)) + if err == nil { + w.maxLinesCurLines++ + w.maxSizeCurSize += len(msg) + } + w.Unlock() + return err } func (w *fileLogWriter) createLogFile() (*os.File, error) { @@ -163,20 +189,20 @@ func (w *fileLogWriter) createLogFile() (*os.File, error) { } func (w *fileLogWriter) initFd() error { - fd := w.mw.fd - finfo, err := fd.Stat() + fd := w.fileWriter + fInfo, err := fd.Stat() if err != nil { return fmt.Errorf("get stat err: %s\n", err) } - w.maxsizeCursize = int(finfo.Size()) - w.dailyOpendate = time.Now().Day() - w.maxlinesCurlines = 0 - if finfo.Size() > 0 { + w.maxSizeCurSize = int(fInfo.Size()) + w.dailyOpenDate = time.Now().Day() + w.maxLinesCurLines = 0 + if fInfo.Size() > 0 { count, err := w.lines() if err != nil { return err } - w.maxlinesCurlines = count + w.maxLinesCurLines = count } return nil } @@ -210,50 +236,47 @@ func (w *fileLogWriter) lines() (int, error) { // DoRotate means it need to write file in new file. // new file name like xx.2013-01-01.2.log -func (w *fileLogWriter) DoRotate() error { +func (w *fileLogWriter) doRotate() error { _, err := os.Lstat(w.Filename) - if err == nil { // file exists - // Find the next available number - num := 1 - fname := "" - suffix := filepath.Ext(w.Filename) - filenameOnly := strings.TrimSuffix(w.Filename, suffix) - if suffix == "" { - suffix = ".log" - } - for ; err == nil && num <= 999; num++ { - fname = filenameOnly + fmt.Sprintf(".%s.%03d%s", time.Now().Format("2006-01-02"), num, suffix) - _, err = os.Lstat(fname) - } - // return error if the last file checked still existed - if err == nil { - return fmt.Errorf("Rotate: Cannot find free log number to rename %s\n", w.Filename) - } - - // block Logger's io.Writer - w.mw.Lock() - defer w.mw.Unlock() - - fd := w.mw.fd - fd.Close() - - // close fd before rename - // Rename the file to its newfound home - err = os.Rename(w.Filename, fname) - if err != nil { - return fmt.Errorf("Rotate: %s\n", err) - } - - // re-start logger - err = w.startLogger() - if err != nil { - return fmt.Errorf("Rotate StartLogger: %s\n", err) - } - - go w.deleteOldLog() + if err != nil { + return err + } + // file exists + // Find the next available number + num := 1 + fName := "" + suffix := filepath.Ext(w.Filename) + filenameOnly := strings.TrimSuffix(w.Filename, suffix) + if suffix == "" { + suffix = ".log" + } + for ; err == nil && num <= 999; num++ { + fName = filenameOnly + fmt.Sprintf(".%s.%03d%s", time.Now().Format("2006-01-02"), num, suffix) + _, err = os.Lstat(fName) + } + // return error if the last file checked still existed + if err == nil { + return fmt.Errorf("Rotate: Cannot find free log number to rename %s\n", w.Filename) } + // close fileWriter before rename + w.fileWriter.Close() + + // Rename the file to its new found name + // even if occurs error,we MUST guarantee to restart new logger + renameErr := os.Rename(w.Filename, fName) + // re-start logger + startLoggerErr := w.startLogger() + go w.deleteOldLog() + + if startLoggerErr != nil { + return fmt.Errorf("Rotate StartLogger: %s\n", startLoggerErr) + } + if renameErr != nil { + return fmt.Errorf("Rotate: %s\n", renameErr) + } return nil + } func (w *fileLogWriter) deleteOldLog() { @@ -261,12 +284,11 @@ func (w *fileLogWriter) deleteOldLog() { filepath.Walk(dir, func(path string, info os.FileInfo, err error) (returnErr error) { defer func() { if r := recover(); r != nil { - returnErr = fmt.Errorf("Unable to delete old log '%s', error: %+v", path, r) - fmt.Println(returnErr) + fmt.Fprintf(os.Stderr, "Unable to delete old log '%s', error: %v\n", path, r) } }() - if !info.IsDir() && info.ModTime().Unix() < (time.Now().Unix()-60*60*24*w.Maxdays) { + if !info.IsDir() && info.ModTime().Unix() < (time.Now().Unix()-60*60*24*w.MaxDays) { if strings.HasPrefix(filepath.Base(path), filepath.Base(w.Filename)) { os.Remove(path) } @@ -275,16 +297,16 @@ func (w *fileLogWriter) deleteOldLog() { }) } -// Destroy close the file desciption, close file writer. +// Destroy close the file description, close file writer. func (w *fileLogWriter) Destroy() { - w.mw.fd.Close() + w.fileWriter.Close() } // Flush flush file logger. // there are no buffering messages in file logger in memory. // flush file means sync file from disk. func (w *fileLogWriter) Flush() { - w.mw.fd.Sync() + w.fileWriter.Sync() } func init() { diff --git a/logs/file_test.go b/logs/file_test.go index 97260f12..f9b54c26 100644 --- a/logs/file_test.go +++ b/logs/file_test.go @@ -23,7 +23,7 @@ import ( "time" ) -func TestFile(t *testing.T) { +func TestFile1(t *testing.T) { log := NewLogger(10000) log.SetLogger("file", `{"filename":"test.log"}`) log.Debug("debug") @@ -34,25 +34,24 @@ func TestFile(t *testing.T) { log.Alert("alert") log.Critical("critical") log.Emergency("emergency") - time.Sleep(time.Second * 4) f, err := os.Open("test.log") if err != nil { t.Fatal(err) } b := bufio.NewReader(f) - linenum := 0 + lineNum := 0 for { line, _, err := b.ReadLine() if err != nil { break } if len(line) > 0 { - linenum++ + lineNum++ } } var expected = LevelDebug + 1 - if linenum != expected { - t.Fatal(linenum, "not "+strconv.Itoa(expected)+" lines") + if lineNum != expected { + t.Fatal(lineNum, "not "+strconv.Itoa(expected)+" lines") } os.Remove("test.log") } @@ -68,25 +67,24 @@ func TestFile2(t *testing.T) { log.Alert("alert") log.Critical("critical") log.Emergency("emergency") - time.Sleep(time.Second * 4) f, err := os.Open("test2.log") if err != nil { t.Fatal(err) } b := bufio.NewReader(f) - linenum := 0 + lineNum := 0 for { line, _, err := b.ReadLine() if err != nil { break } if len(line) > 0 { - linenum++ + lineNum++ } } var expected = LevelError + 1 - if linenum != expected { - t.Fatal(linenum, "not "+strconv.Itoa(expected)+" lines") + if lineNum != expected { + t.Fatal(lineNum, "not "+strconv.Itoa(expected)+" lines") } os.Remove("test2.log") } @@ -102,13 +100,13 @@ func TestFileRotate(t *testing.T) { log.Alert("alert") log.Critical("critical") log.Emergency("emergency") - time.Sleep(time.Second * 4) - rotatename := "test3" + fmt.Sprintf(".%s.%03d", time.Now().Format("2006-01-02"), 1) + ".log" - b, err := exists(rotatename) + rotateName := "test3" + fmt.Sprintf(".%s.%03d", time.Now().Format("2006-01-02"), 1) + ".log" + b, err := exists(rotateName) if !b || err != nil { + os.Remove("test3.log") t.Fatal("rotate not generated") } - os.Remove(rotatename) + os.Remove(rotateName) os.Remove("test3.log") } @@ -131,3 +129,46 @@ func BenchmarkFile(b *testing.B) { } os.Remove("test4.log") } + + +func BenchmarkFileAsynchronous(b *testing.B) { + log := NewLogger(100000) + log.SetLogger("file", `{"filename":"test4.log"}`) + log.Async() + for i := 0; i < b.N; i++ { + log.Debug("debug") + } + os.Remove("test4.log") +} + +func BenchmarkFileCallDepth(b *testing.B) { + log := NewLogger(100000) + log.SetLogger("file", `{"filename":"test4.log"}`) + log.EnableFuncCallDepth(true) + log.SetLogFuncCallDepth(2) + for i := 0; i < b.N; i++ { + log.Debug("debug") + } + os.Remove("test4.log") +} + +func BenchmarkFileAsynchronousCallDepth(b *testing.B) { + log := NewLogger(100000) + log.SetLogger("file", `{"filename":"test4.log"}`) + log.EnableFuncCallDepth(true) + log.SetLogFuncCallDepth(2) + log.Async() + for i := 0; i < b.N; i++ { + log.Debug("debug") + } + os.Remove("test4.log") +} + +func BenchmarkFileOnGoroutine(b *testing.B) { + log := NewLogger(100000) + log.SetLogger("file", `{"filename":"test4.log"}`) + for i := 0; i < b.N; i++ { + go log.Debug("debug") + } + os.Remove("test4.log") +} diff --git a/logs/log.go b/logs/log.go index 28b5937c..ccaaa3ad 100644 --- a/logs/log.go +++ b/logs/log.go @@ -35,8 +35,10 @@ package logs import ( "fmt" + "os" "path" "runtime" + "strconv" "sync" ) @@ -94,8 +96,13 @@ type BeeLogger struct { enableFuncCallDepth bool loggerFuncCallDepth int asynchronous bool - msg chan *logMsg - outputs map[string]Logger + msgChan chan *logMsg + outputs []*nameLogger +} + +type nameLogger struct { + Logger + name string } type logMsg struct { @@ -103,59 +110,79 @@ type logMsg struct { msg string } +var logMsgPool *sync.Pool + // NewLogger returns a new BeeLogger. -// channellen means the number of messages in chan. +// channelLen means the number of messages in chan(used where asynchronous is true). // if the buffering chan is full, logger adapters write to file or other way. -func NewLogger(channellen int64) *BeeLogger { +func NewLogger(channelLen int64) *BeeLogger { bl := new(BeeLogger) bl.level = LevelDebug bl.loggerFuncCallDepth = 2 - bl.msg = make(chan *logMsg, channellen) - bl.outputs = make(map[string]Logger) + bl.msgChan = make(chan *logMsg, channelLen) return bl } // Async set the log to asynchronous and start the goroutine func (bl *BeeLogger) Async() *BeeLogger { bl.asynchronous = true + logMsgPool = &sync.Pool{ + New: func() interface{} { + return &logMsg{} + }, + } go bl.startLogger() return bl } // SetLogger provides a given logger adapter into BeeLogger with config string. // config need to be correct JSON as string: {"interval":360}. -func (bl *BeeLogger) SetLogger(adaptername string, config string) error { +func (bl *BeeLogger) SetLogger(adapterName string, config string) error { bl.lock.Lock() defer bl.lock.Unlock() - if log, ok := adapters[adaptername]; ok { + if log, ok := adapters[adapterName]; ok { lg := log() err := lg.Init(config) - bl.outputs[adaptername] = lg if err != nil { - fmt.Println("logs.BeeLogger.SetLogger: " + err.Error()) + fmt.Fprintln(os.Stderr, "logs.BeeLogger.SetLogger: "+err.Error()) return err } + bl.outputs = append(bl.outputs, &nameLogger{name: adapterName, Logger: lg}) } else { - return fmt.Errorf("logs: unknown adaptername %q (forgotten Register?)", adaptername) + return fmt.Errorf("logs: unknown adaptername %q (forgotten Register?)", adapterName) } return nil } // DelLogger remove a logger adapter in BeeLogger. -func (bl *BeeLogger) DelLogger(adaptername string) error { +func (bl *BeeLogger) DelLogger(adapterName string) error { bl.lock.Lock() defer bl.lock.Unlock() - if lg, ok := bl.outputs[adaptername]; ok { - lg.Destroy() - delete(bl.outputs, adaptername) - return nil + outputs := []*nameLogger{} + for _, lg := range bl.outputs { + if lg.name == adapterName { + lg.Destroy() + } else { + outputs = append(outputs, lg) + } } - return fmt.Errorf("logs: unknown adaptername %q (forgotten Register?)", adaptername) + if len(outputs) == len(bl.outputs) { + return fmt.Errorf("logs: unknown adaptername %q (forgotten Register?)", adapterName) + } + bl.outputs = outputs + return nil } -func (bl *BeeLogger) writerMsg(loglevel int, msg string) error { - lm := new(logMsg) - lm.level = loglevel +func (bl *BeeLogger) writeToLoggers(msg string, level int) { + for _, l := range bl.outputs { + err := l.WriteMsg(msg, level) + if err != nil { + fmt.Fprintf(os.Stderr, "unable to WriteMsg to adapter:%v,error:%v\n", l.name, err) + } + } +} + +func (bl *BeeLogger) writeMsg(logLevel int, msg string) error { if bl.enableFuncCallDepth { _, file, line, ok := runtime.Caller(bl.loggerFuncCallDepth) if !ok { @@ -163,20 +190,15 @@ func (bl *BeeLogger) writerMsg(loglevel int, msg string) error { line = 0 } _, filename := path.Split(file) - lm.msg = fmt.Sprintf("[%s:%d] %s", filename, line, msg) - } else { - lm.msg = msg + msg = "[" + filename + ":" + strconv.FormatInt(int64(line), 10) + "]" + msg } if bl.asynchronous { - bl.msg <- lm + lm := logMsgPool.Get().(*logMsg) + lm.level = logLevel + lm.msg = msg + bl.msgChan <- lm } else { - for name, l := range bl.outputs { - err := l.WriteMsg(lm.msg, lm.level) - if err != nil { - fmt.Println("unable to WriteMsg to adapter:", name, err) - return err - } - } + bl.writeToLoggers(msg, logLevel) } return nil } @@ -208,13 +230,9 @@ func (bl *BeeLogger) EnableFuncCallDepth(b bool) { func (bl *BeeLogger) startLogger() { for { select { - case bm := <-bl.msg: - for _, l := range bl.outputs { - err := l.WriteMsg(bm.msg, bm.level) - if err != nil { - fmt.Println("ERROR, unable to WriteMsg:", err) - } - } + case bm := <-bl.msgChan: + bl.writeToLoggers(bm.msg, bm.level) + logMsgPool.Put(bm) } } } @@ -225,7 +243,7 @@ func (bl *BeeLogger) Emergency(format string, v ...interface{}) { return } msg := fmt.Sprintf("[M] "+format, v...) - bl.writerMsg(LevelEmergency, msg) + bl.writeMsg(LevelEmergency, msg) } // Alert Log ALERT level message. @@ -234,7 +252,7 @@ func (bl *BeeLogger) Alert(format string, v ...interface{}) { return } msg := fmt.Sprintf("[A] "+format, v...) - bl.writerMsg(LevelAlert, msg) + bl.writeMsg(LevelAlert, msg) } // Critical Log CRITICAL level message. @@ -243,7 +261,7 @@ func (bl *BeeLogger) Critical(format string, v ...interface{}) { return } msg := fmt.Sprintf("[C] "+format, v...) - bl.writerMsg(LevelCritical, msg) + bl.writeMsg(LevelCritical, msg) } // Error Log ERROR level message. @@ -252,7 +270,7 @@ func (bl *BeeLogger) Error(format string, v ...interface{}) { return } msg := fmt.Sprintf("[E] "+format, v...) - bl.writerMsg(LevelError, msg) + bl.writeMsg(LevelError, msg) } // Warning Log WARNING level message. @@ -261,7 +279,7 @@ func (bl *BeeLogger) Warning(format string, v ...interface{}) { return } msg := fmt.Sprintf("[W] "+format, v...) - bl.writerMsg(LevelWarning, msg) + bl.writeMsg(LevelWarning, msg) } // Notice Log NOTICE level message. @@ -270,7 +288,7 @@ func (bl *BeeLogger) Notice(format string, v ...interface{}) { return } msg := fmt.Sprintf("[N] "+format, v...) - bl.writerMsg(LevelNotice, msg) + bl.writeMsg(LevelNotice, msg) } // Informational Log INFORMATIONAL level message. @@ -279,7 +297,7 @@ func (bl *BeeLogger) Informational(format string, v ...interface{}) { return } msg := fmt.Sprintf("[I] "+format, v...) - bl.writerMsg(LevelInformational, msg) + bl.writeMsg(LevelInformational, msg) } // Debug Log DEBUG level message. @@ -288,7 +306,7 @@ func (bl *BeeLogger) Debug(format string, v ...interface{}) { return } msg := fmt.Sprintf("[D] "+format, v...) - bl.writerMsg(LevelDebug, msg) + bl.writeMsg(LevelDebug, msg) } // Warn Log WARN level message. @@ -298,7 +316,7 @@ func (bl *BeeLogger) Warn(format string, v ...interface{}) { return } msg := fmt.Sprintf("[W] "+format, v...) - bl.writerMsg(LevelWarning, msg) + bl.writeMsg(LevelWarning, msg) } // Info Log INFO level message. @@ -308,7 +326,7 @@ func (bl *BeeLogger) Info(format string, v ...interface{}) { return } msg := fmt.Sprintf("[I] "+format, v...) - bl.writerMsg(LevelInformational, msg) + bl.writeMsg(LevelInformational, msg) } // Trace Log TRACE level message. @@ -318,7 +336,7 @@ func (bl *BeeLogger) Trace(format string, v ...interface{}) { return } msg := fmt.Sprintf("[D] "+format, v...) - bl.writerMsg(LevelDebug, msg) + bl.writeMsg(LevelDebug, msg) } // Flush flush all chan data. @@ -331,14 +349,10 @@ func (bl *BeeLogger) Flush() { // Close close logger, flush all chan data and destroy all adapters in BeeLogger. func (bl *BeeLogger) Close() { for { - if len(bl.msg) > 0 { - bm := <-bl.msg - for _, l := range bl.outputs { - err := l.WriteMsg(bm.msg, bm.level) - if err != nil { - fmt.Println("ERROR, unable to WriteMsg (while closing logger):", err) - } - } + if len(bl.msgChan) > 0 { + bm := <-bl.msgChan + bl.writeToLoggers(bm.msg, bm.level) + logMsgPool.Put(bm) continue } break