1
0
mirror of https://github.com/astaxie/beego.git synced 2024-11-22 06:20:54 +00:00

Merge pull request #1560 from JessonChan/log_enhancement

Log enhancement
This commit is contained in:
astaxie 2016-01-13 22:57:39 +08:00
commit 0eaf923a27
4 changed files with 267 additions and 198 deletions

View File

@ -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")
}
}

View File

@ -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() {

View File

@ -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")
}

View File

@ -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