diff options
author | zeripath <art27@cantab.net> | 2019-04-02 08:48:31 +0100 |
---|---|---|
committer | GitHub <noreply@github.com> | 2019-04-02 08:48:31 +0100 |
commit | 704da08fdc6bae6fdd6bf1b892ebe12afeef5eca (patch) | |
tree | e0613ab3ba0d4336b0912bbad8862f503ec180f6 /modules/log | |
parent | ef2a343e27d8af2de0bb696bd60d9a019e1e8b69 (diff) | |
download | gitea-704da08fdc6bae6fdd6bf1b892ebe12afeef5eca.tar.gz gitea-704da08fdc6bae6fdd6bf1b892ebe12afeef5eca.zip |
Better logging (#6038) (#6095)
* Panic don't fatal on create new logger
Fixes #5854
Signed-off-by: Andrew Thornton <art27@cantab.net>
* partial broken
* Update the logging infrastrcture
Signed-off-by: Andrew Thornton <art27@cantab.net>
* Reset the skip levels for Fatal and Error
Signed-off-by: Andrew Thornton <art27@cantab.net>
* broken ncsa
* More log.Error fixes
Signed-off-by: Andrew Thornton <art27@cantab.net>
* Remove nal
* set log-levels to lowercase
* Make console_test test all levels
* switch to lowercased levels
* OK now working
* Fix vetting issues
* Fix lint
* Fix tests
* change default logging to match current gitea
* Improve log testing
Signed-off-by: Andrew Thornton <art27@cantab.net>
* reset error skip levels to 0
* Update documentation and access logger configuration
* Redirect the router log back to gitea if redirect macaron log but also allow setting the log level - i.e. TRACE
* Fix broken level caching
* Refactor the router log
* Add Router logger
* Add colorizing options
* Adjust router colors
* Only create logger if they will be used
* update app.ini.sample
* rename Attribute ColorAttribute
* Change from white to green for function
* Set fatal/error levels
* Restore initial trace logger
* Fix Trace arguments in modules/auth/auth.go
* Properly handle XORMLogger
* Improve admin/config page
* fix fmt
* Add auto-compression of old logs
* Update error log levels
* Remove the unnecessary skip argument from Error, Fatal and Critical
* Add stacktrace support
* Fix tests
* Remove x/sync from vendors?
* Add stderr option to console logger
* Use filepath.ToSlash to protect against Windows in tests
* Remove prefixed underscores from names in colors.go
* Remove not implemented database logger
This was removed from Gogs on 4 Mar 2016 but left in the configuration
since then.
* Ensure that log paths are relative to ROOT_PATH
* use path.Join
* rename jsonConfig to logConfig
* Rename "config" to "jsonConfig" to make it clearer
* Requested changes
* Requested changes: XormLogger
* Try to color the windows terminal
If successful default to colorizing the console logs
* fixup
* Colorize initially too
* update vendor
* Colorize logs on default and remove if this is not a colorizing logger
* Fix documentation
* fix test
* Use go-isatty to detect if on windows we are on msys or cygwin
* Fix spelling mistake
* Add missing vendors
* More changes
* Rationalise the ANSI writer protection
* Adjust colors on advice from @0x5c
* Make Flags a comma separated list
* Move to use the windows constant for ENABLE_VIRTUAL_TERMINAL_PROCESSING
* Ensure matching is done on the non-colored message - to simpify EXPRESSION
Diffstat (limited to 'modules/log')
-rw-r--r-- | modules/log/base.go | 328 | ||||
-rw-r--r-- | modules/log/base_test.go | 277 | ||||
-rw-r--r-- | modules/log/colors.go | 348 | ||||
-rw-r--r-- | modules/log/conn.go | 122 | ||||
-rw-r--r-- | modules/log/conn_test.go | 240 | ||||
-rw-r--r-- | modules/log/console.go | 88 | ||||
-rw-r--r-- | modules/log/console_test.go | 137 | ||||
-rw-r--r-- | modules/log/console_windows.go | 43 | ||||
-rw-r--r-- | modules/log/errors.go | 62 | ||||
-rw-r--r-- | modules/log/event.go | 335 | ||||
-rw-r--r-- | modules/log/file.go | 209 | ||||
-rw-r--r-- | modules/log/file_test.go | 247 | ||||
-rw-r--r-- | modules/log/level.go | 111 | ||||
-rw-r--r-- | modules/log/level_test.go | 55 | ||||
-rw-r--r-- | modules/log/log.go | 451 | ||||
-rw-r--r-- | modules/log/log_test.go | 154 | ||||
-rw-r--r-- | modules/log/logger.go | 156 | ||||
-rw-r--r-- | modules/log/provider.go | 26 | ||||
-rw-r--r-- | modules/log/router.go | 103 | ||||
-rw-r--r-- | modules/log/smtp.go | 82 | ||||
-rw-r--r-- | modules/log/smtp_test.go | 86 | ||||
-rw-r--r-- | modules/log/stack.go | 83 | ||||
-rw-r--r-- | modules/log/xorm.go | 91 |
23 files changed, 3259 insertions, 575 deletions
diff --git a/modules/log/base.go b/modules/log/base.go new file mode 100644 index 0000000000..5577737e04 --- /dev/null +++ b/modules/log/base.go @@ -0,0 +1,328 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "bytes" + "fmt" + "io" + "regexp" + "strings" + "sync" +) + +// These flags define which text to prefix to each log entry generated +// by the Logger. Bits are or'ed together to control what's printed. +// There is no control over the order they appear (the order listed +// here) or the format they present (as described in the comments). +// The prefix is followed by a colon only if more than time is stated +// is specified. For example, flags Ldate | Ltime +// produce, 2009/01/23 01:23:23 message. +// The standard is: +// 2009/01/23 01:23:23 ...a/b/c/d.go:23:runtime.Caller() [I]: message +const ( + Ldate = 1 << iota // the date in the local time zone: 2009/01/23 + Ltime // the time in the local time zone: 01:23:23 + Lmicroseconds // microsecond resolution: 01:23:23.123123. assumes Ltime. + Llongfile // full file name and line number: /a/b/c/d.go:23 + Lshortfile // final file name element and line number: d.go:23. overrides Llongfile + Lfuncname // function name of the caller: runtime.Caller() + Lshortfuncname // last part of the function name + LUTC // if Ldate or Ltime is set, use UTC rather than the local time zone + Llevelinitial // Initial character of the provided level in brackets eg. [I] for info + Llevel // Provided level in brackets [INFO] + + // Last 20 characters of the filename + Lmedfile = Lshortfile | Llongfile + + // LstdFlags is the initial value for the standard logger + LstdFlags = Ldate | Ltime | Lmedfile | Lshortfuncname | Llevelinitial +) + +var flagFromString = map[string]int{ + "none": 0, + "date": Ldate, + "time": Ltime, + "microseconds": Lmicroseconds, + "longfile": Llongfile, + "shortfile": Lshortfile, + "funcname": Lfuncname, + "shortfuncname": Lshortfuncname, + "utc": LUTC, + "levelinitial": Llevelinitial, + "level": Llevel, + "medfile": Lmedfile, + "stdflags": LstdFlags, +} + +// FlagsFromString takes a comma separated list of flags and returns +// the flags for this string +func FlagsFromString(from string) int { + flags := 0 + for _, flag := range strings.Split(strings.ToLower(from), ",") { + f, ok := flagFromString[strings.TrimSpace(flag)] + if ok { + flags = flags | f + } + } + return flags +} + +type byteArrayWriter []byte + +func (b *byteArrayWriter) Write(p []byte) (int, error) { + *b = append(*b, p...) + return len(p), nil +} + +// BaseLogger represent a basic logger for Gitea +type BaseLogger struct { + out io.WriteCloser + mu sync.Mutex + + Level Level `json:"level"` + StacktraceLevel Level `json:"stacktraceLevel"` + Flags int `json:"flags"` + Prefix string `json:"prefix"` + Colorize bool `json:"colorize"` + Expression string `json:"expression"` + regexp *regexp.Regexp +} + +func (b *BaseLogger) createLogger(out io.WriteCloser, level ...Level) { + b.mu.Lock() + defer b.mu.Unlock() + b.out = out + switch b.Flags { + case 0: + b.Flags = LstdFlags + case -1: + b.Flags = 0 + } + if len(level) > 0 { + b.Level = level[0] + } + b.createExpression() +} + +func (b *BaseLogger) createExpression() { + if len(b.Expression) > 0 { + var err error + b.regexp, err = regexp.Compile(b.Expression) + if err != nil { + b.regexp = nil + } + } +} + +// GetLevel returns the logging level for this logger +func (b *BaseLogger) GetLevel() Level { + return b.Level +} + +// GetStacktraceLevel returns the stacktrace logging level for this logger +func (b *BaseLogger) GetStacktraceLevel() Level { + return b.StacktraceLevel +} + +// Copy of cheap integer to fixed-width decimal to ascii from logger. +func itoa(buf *[]byte, i int, wid int) { + var b [20]byte + bp := len(b) - 1 + for i >= 10 || wid > 1 { + wid-- + q := i / 10 + b[bp] = byte('0' + i - q*10) + bp-- + i = q + } + // i < 10 + b[bp] = byte('0' + i) + *buf = append(*buf, b[bp:]...) +} + +func (b *BaseLogger) createMsg(buf *[]byte, event *Event) { + *buf = append(*buf, b.Prefix...) + t := event.time + if b.Flags&(Ldate|Ltime|Lmicroseconds) != 0 { + if b.Colorize { + *buf = append(*buf, fgCyanBytes...) + } + if b.Flags&LUTC != 0 { + t = t.UTC() + } + if b.Flags&Ldate != 0 { + year, month, day := t.Date() + itoa(buf, year, 4) + *buf = append(*buf, '/') + itoa(buf, int(month), 2) + *buf = append(*buf, '/') + itoa(buf, day, 2) + *buf = append(*buf, ' ') + } + if b.Flags&(Ltime|Lmicroseconds) != 0 { + hour, min, sec := t.Clock() + itoa(buf, hour, 2) + *buf = append(*buf, ':') + itoa(buf, min, 2) + *buf = append(*buf, ':') + itoa(buf, sec, 2) + if b.Flags&Lmicroseconds != 0 { + *buf = append(*buf, '.') + itoa(buf, t.Nanosecond()/1e3, 6) + } + *buf = append(*buf, ' ') + } + if b.Colorize { + *buf = append(*buf, resetBytes...) + } + + } + if b.Flags&(Lshortfile|Llongfile) != 0 { + if b.Colorize { + *buf = append(*buf, fgGreenBytes...) + } + file := event.filename + if b.Flags&Lmedfile == Lmedfile { + startIndex := len(file) - 20 + if startIndex > 0 { + file = "..." + file[startIndex:] + } + } else if b.Flags&Lshortfile != 0 { + startIndex := strings.LastIndexByte(file, '/') + if startIndex > 0 && startIndex < len(file) { + file = file[startIndex+1:] + } + } + *buf = append(*buf, file...) + *buf = append(*buf, ':') + itoa(buf, event.line, -1) + if b.Flags&(Lfuncname|Lshortfuncname) != 0 { + *buf = append(*buf, ':') + } else { + if b.Colorize { + *buf = append(*buf, resetBytes...) + } + *buf = append(*buf, ' ') + } + } + if b.Flags&(Lfuncname|Lshortfuncname) != 0 { + if b.Colorize { + *buf = append(*buf, fgGreenBytes...) + } + funcname := event.caller + if b.Flags&Lshortfuncname != 0 { + lastIndex := strings.LastIndexByte(funcname, '.') + if lastIndex > 0 && len(funcname) > lastIndex+1 { + funcname = funcname[lastIndex+1:] + } + } + *buf = append(*buf, funcname...) + if b.Colorize { + *buf = append(*buf, resetBytes...) + } + *buf = append(*buf, ' ') + + } + if b.Flags&(Llevel|Llevelinitial) != 0 { + level := strings.ToUpper(event.level.String()) + if b.Colorize { + *buf = append(*buf, levelToColor[event.level]...) + } + *buf = append(*buf, '[') + if b.Flags&Llevelinitial != 0 { + *buf = append(*buf, level[0]) + } else { + *buf = append(*buf, level...) + } + *buf = append(*buf, ']') + if b.Colorize { + *buf = append(*buf, resetBytes...) + } + *buf = append(*buf, ' ') + } + + var msg = []byte(event.msg) + if len(msg) > 0 && msg[len(msg)-1] == '\n' { + msg = msg[:len(msg)-1] + } + + pawMode := allowColor + if !b.Colorize { + pawMode = removeColor + } + + baw := byteArrayWriter(*buf) + (&protectedANSIWriter{ + w: &baw, + mode: pawMode, + }).Write([]byte(msg)) + *buf = baw + + if event.stacktrace != "" && b.StacktraceLevel <= event.level { + lines := bytes.Split([]byte(event.stacktrace), []byte("\n")) + if len(lines) > 1 { + for _, line := range lines { + *buf = append(*buf, "\n\t"...) + *buf = append(*buf, line...) + } + } + *buf = append(*buf, '\n') + } + *buf = append(*buf, '\n') +} + +// LogEvent logs the event to the internal writer +func (b *BaseLogger) LogEvent(event *Event) error { + if b.Level > event.level { + return nil + } + + b.mu.Lock() + defer b.mu.Unlock() + if !b.Match(event) { + return nil + } + var buf []byte + b.createMsg(&buf, event) + _, err := b.out.Write(buf) + return err +} + +// Match checks if the given event matches the logger's regexp expression +func (b *BaseLogger) Match(event *Event) bool { + if b.regexp == nil { + return true + } + if b.regexp.Match([]byte(fmt.Sprintf("%s:%d:%s", event.filename, event.line, event.caller))) { + return true + } + // Match on the non-colored msg - therefore strip out colors + var msg []byte + baw := byteArrayWriter(msg) + (&protectedANSIWriter{ + w: &baw, + mode: removeColor, + }).Write([]byte(event.msg)) + msg = baw + if b.regexp.Match(msg) { + return true + } + return false +} + +// Close the base logger +func (b *BaseLogger) Close() { + b.mu.Lock() + defer b.mu.Unlock() + if b.out != nil { + b.out.Close() + } +} + +// GetName returns empty for these provider loggers +func (b *BaseLogger) GetName() string { + return "" +} diff --git a/modules/log/base_test.go b/modules/log/base_test.go new file mode 100644 index 0000000000..3686c26ce8 --- /dev/null +++ b/modules/log/base_test.go @@ -0,0 +1,277 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "fmt" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" +) + +type CallbackWriteCloser struct { + callback func([]byte, bool) +} + +func (c CallbackWriteCloser) Write(p []byte) (int, error) { + c.callback(p, false) + return len(p), nil +} + +func (c CallbackWriteCloser) Close() error { + c.callback(nil, true) + return nil +} + +func TestBaseLogger(t *testing.T) { + var written []byte + var closed bool + + c := CallbackWriteCloser{ + callback: func(p []byte, close bool) { + written = p + closed = close + }, + } + prefix := "TestPrefix " + b := BaseLogger{ + out: c, + Level: INFO, + Flags: LstdFlags | LUTC, + Prefix: prefix, + } + location, _ := time.LoadLocation("EST") + + date := time.Date(2019, time.January, 13, 22, 3, 30, 15, location) + + dateString := date.UTC().Format("2006/01/02 15:04:05") + + event := Event{ + level: INFO, + msg: "TEST MSG", + caller: "CALLER", + filename: "FULL/FILENAME", + line: 1, + time: date, + } + + assert.Equal(t, INFO, b.GetLevel()) + + expected := fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + event.level = DEBUG + expected = "" + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + + event.level = TRACE + expected = "" + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + + event.level = WARN + expected = fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + event.level = ERROR + expected = fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + event.level = CRITICAL + expected = fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + b.Close() + assert.Equal(t, true, closed) +} + +func TestBaseLoggerDated(t *testing.T) { + var written []byte + var closed bool + + c := CallbackWriteCloser{ + callback: func(p []byte, close bool) { + written = p + closed = close + }, + } + prefix := "" + b := BaseLogger{ + out: c, + Level: WARN, + Flags: Ldate | Ltime | Lmicroseconds | Lshortfile | Llevel, + Prefix: prefix, + } + + location, _ := time.LoadLocation("EST") + + date := time.Date(2019, time.January, 13, 22, 3, 30, 115, location) + + dateString := date.Format("2006/01/02 15:04:05.000000") + + event := Event{ + level: WARN, + msg: "TEST MESSAGE TEST\n", + caller: "CALLER", + filename: "FULL/FILENAME", + line: 1, + time: date, + } + + assert.Equal(t, WARN, b.GetLevel()) + + expected := fmt.Sprintf("%s%s %s:%d [%s] %s", prefix, dateString, "FILENAME", event.line, strings.ToUpper(event.level.String()), event.msg) + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + event.level = INFO + expected = "" + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + event.level = ERROR + expected = fmt.Sprintf("%s%s %s:%d [%s] %s", prefix, dateString, "FILENAME", event.line, strings.ToUpper(event.level.String()), event.msg) + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + event.level = DEBUG + expected = "" + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + event.level = CRITICAL + expected = fmt.Sprintf("%s%s %s:%d [%s] %s", prefix, dateString, "FILENAME", event.line, strings.ToUpper(event.level.String()), event.msg) + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + event.level = TRACE + expected = "" + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + b.Close() + assert.Equal(t, true, closed) +} + +func TestBaseLoggerMultiLineNoFlagsRegexp(t *testing.T) { + var written []byte + var closed bool + + c := CallbackWriteCloser{ + callback: func(p []byte, close bool) { + written = p + closed = close + }, + } + prefix := "" + b := BaseLogger{ + Level: DEBUG, + StacktraceLevel: ERROR, + Flags: -1, + Prefix: prefix, + Expression: "FILENAME", + } + b.createLogger(c) + + location, _ := time.LoadLocation("EST") + + date := time.Date(2019, time.January, 13, 22, 3, 30, 115, location) + + event := Event{ + level: DEBUG, + msg: "TEST\nMESSAGE\nTEST", + caller: "CALLER", + filename: "FULL/FILENAME", + line: 1, + time: date, + } + + assert.Equal(t, DEBUG, b.GetLevel()) + + expected := "TEST\n\tMESSAGE\n\tTEST\n" + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + event.filename = "ELSEWHERE" + + b.LogEvent(&event) + assert.Equal(t, "", string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + event.caller = "FILENAME" + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + event = Event{ + level: DEBUG, + msg: "TEST\nFILENAME\nTEST", + caller: "CALLER", + filename: "FULL/ELSEWHERE", + line: 1, + time: date, + } + expected = "TEST\n\tFILENAME\n\tTEST\n" + b.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + +} + +func TestBrokenRegexp(t *testing.T) { + var closed bool + + c := CallbackWriteCloser{ + callback: func(p []byte, close bool) { + closed = close + }, + } + + b := BaseLogger{ + Level: DEBUG, + StacktraceLevel: ERROR, + Flags: -1, + Prefix: prefix, + Expression: "\\", + } + b.createLogger(c) + assert.Empty(t, b.regexp) + b.Close() + assert.Equal(t, true, closed) +} diff --git a/modules/log/colors.go b/modules/log/colors.go new file mode 100644 index 0000000000..fa8a664f08 --- /dev/null +++ b/modules/log/colors.go @@ -0,0 +1,348 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "fmt" + "io" + "strconv" + "strings" +) + +const escape = "\033" + +// ColorAttribute defines a single SGR Code +type ColorAttribute int + +// Base ColorAttributes +const ( + Reset ColorAttribute = iota + Bold + Faint + Italic + Underline + BlinkSlow + BlinkRapid + ReverseVideo + Concealed + CrossedOut +) + +// Foreground text colors +const ( + FgBlack ColorAttribute = iota + 30 + FgRed + FgGreen + FgYellow + FgBlue + FgMagenta + FgCyan + FgWhite +) + +// Foreground Hi-Intensity text colors +const ( + FgHiBlack ColorAttribute = iota + 90 + FgHiRed + FgHiGreen + FgHiYellow + FgHiBlue + FgHiMagenta + FgHiCyan + FgHiWhite +) + +// Background text colors +const ( + BgBlack ColorAttribute = iota + 40 + BgRed + BgGreen + BgYellow + BgBlue + BgMagenta + BgCyan + BgWhite +) + +// Background Hi-Intensity text colors +const ( + BgHiBlack ColorAttribute = iota + 100 + BgHiRed + BgHiGreen + BgHiYellow + BgHiBlue + BgHiMagenta + BgHiCyan + BgHiWhite +) + +var colorAttributeToString = map[ColorAttribute]string{ + Reset: "Reset", + Bold: "Bold", + Faint: "Faint", + Italic: "Italic", + Underline: "Underline", + BlinkSlow: "BlinkSlow", + BlinkRapid: "BlinkRapid", + ReverseVideo: "ReverseVideo", + Concealed: "Concealed", + CrossedOut: "CrossedOut", + FgBlack: "FgBlack", + FgRed: "FgRed", + FgGreen: "FgGreen", + FgYellow: "FgYellow", + FgBlue: "FgBlue", + FgMagenta: "FgMagenta", + FgCyan: "FgCyan", + FgWhite: "FgWhite", + FgHiBlack: "FgHiBlack", + FgHiRed: "FgHiRed", + FgHiGreen: "FgHiGreen", + FgHiYellow: "FgHiYellow", + FgHiBlue: "FgHiBlue", + FgHiMagenta: "FgHiMagenta", + FgHiCyan: "FgHiCyan", + FgHiWhite: "FgHiWhite", + BgBlack: "BgBlack", + BgRed: "BgRed", + BgGreen: "BgGreen", + BgYellow: "BgYellow", + BgBlue: "BgBlue", + BgMagenta: "BgMagenta", + BgCyan: "BgCyan", + BgWhite: "BgWhite", + BgHiBlack: "BgHiBlack", + BgHiRed: "BgHiRed", + BgHiGreen: "BgHiGreen", + BgHiYellow: "BgHiYellow", + BgHiBlue: "BgHiBlue", + BgHiMagenta: "BgHiMagenta", + BgHiCyan: "BgHiCyan", + BgHiWhite: "BgHiWhite", +} + +func (c *ColorAttribute) String() string { + return colorAttributeToString[*c] +} + +var colorAttributeFromString = map[string]ColorAttribute{} + +// ColorAttributeFromString will return a ColorAttribute given a string +func ColorAttributeFromString(from string) ColorAttribute { + lowerFrom := strings.TrimSpace(strings.ToLower(from)) + return colorAttributeFromString[lowerFrom] +} + +// ColorString converts a list of ColorAttributes to a color string +func ColorString(attrs ...ColorAttribute) string { + return string(ColorBytes(attrs...)) +} + +// ColorBytes converts a list of ColorAttributes to a byte array +func ColorBytes(attrs ...ColorAttribute) []byte { + bytes := make([]byte, 0, 20) + bytes = append(bytes, escape[0], '[') + if len(attrs) > 0 { + bytes = append(bytes, strconv.Itoa(int(attrs[0]))...) + for _, a := range attrs[1:] { + bytes = append(bytes, ';') + bytes = append(bytes, strconv.Itoa(int(a))...) + } + } else { + bytes = append(bytes, strconv.Itoa(int(Bold))...) + } + bytes = append(bytes, 'm') + return bytes +} + +var levelToColor = map[Level]string{ + TRACE: ColorString(Bold, FgCyan), + DEBUG: ColorString(Bold, FgBlue), + INFO: ColorString(Bold, FgGreen), + WARN: ColorString(Bold, FgYellow), + ERROR: ColorString(Bold, FgRed), + CRITICAL: ColorString(Bold, BgMagenta), + FATAL: ColorString(Bold, BgRed), + NONE: ColorString(Reset), +} + +var resetBytes = ColorBytes(Reset) +var fgCyanBytes = ColorBytes(FgCyan) +var fgGreenBytes = ColorBytes(FgGreen) +var fgBoldBytes = ColorBytes(Bold) + +type protectedANSIWriterMode int + +const ( + escapeAll protectedANSIWriterMode = iota + allowColor + removeColor +) + +type protectedANSIWriter struct { + w io.Writer + mode protectedANSIWriterMode +} + +// Write will protect against unusual characters +func (c *protectedANSIWriter) Write(bytes []byte) (int, error) { + end := len(bytes) + totalWritten := 0 +normalLoop: + for i := 0; i < end; { + lasti := i + + if c.mode == escapeAll { + for i < end && (bytes[i] >= ' ' || bytes[i] == '\n') { + i++ + } + } else { + for i < end && bytes[i] >= ' ' { + i++ + } + } + + if i > lasti { + written, err := c.w.Write(bytes[lasti:i]) + totalWritten = totalWritten + written + if err != nil { + return totalWritten, err + } + + } + if i >= end { + break + } + + // If we're not just escaping all we should prefix all newlines with a \t + if c.mode != escapeAll { + if bytes[i] == '\n' { + written, err := c.w.Write([]byte{'\n', '\t'}) + if written > 0 { + totalWritten++ + } + if err != nil { + return totalWritten, err + } + i++ + continue normalLoop + } + + if bytes[i] == escape[0] && i+1 < end && bytes[i+1] == '[' { + for j := i + 2; j < end; j++ { + if bytes[j] >= '0' && bytes[j] <= '9' { + continue + } + if bytes[j] == ';' { + continue + } + if bytes[j] == 'm' { + if c.mode == allowColor { + written, err := c.w.Write(bytes[i : j+1]) + totalWritten = totalWritten + written + if err != nil { + return totalWritten, err + } + } else { + totalWritten = j + } + i = j + 1 + continue normalLoop + } + break + } + } + } + + // Process naughty character + if _, err := fmt.Fprintf(c.w, `\%#o03d`, bytes[i]); err != nil { + return totalWritten, err + } + i++ + totalWritten++ + } + return totalWritten, nil +} + +// ColoredValue will Color the provided value +type ColoredValue struct { + ColorBytes *[]byte + ResetBytes *[]byte + Value *interface{} +} + +// NewColoredValue is a helper function to create a ColoredValue from a Value +// If no color is provided it defaults to Bold with standard Reset +// If a ColoredValue is provided it is not changed +func NewColoredValue(value interface{}, color ...ColorAttribute) *ColoredValue { + return NewColoredValuePointer(&value, color...) +} + +// NewColoredValuePointer is a helper function to create a ColoredValue from a Value Pointer +// If no color is provided it defaults to Bold with standard Reset +// If a ColoredValue is provided it is not changed +func NewColoredValuePointer(value *interface{}, color ...ColorAttribute) *ColoredValue { + if val, ok := (*value).(*ColoredValue); ok { + return val + } + if len(color) > 0 { + bytes := ColorBytes(color...) + return &ColoredValue{ + ColorBytes: &bytes, + ResetBytes: &resetBytes, + Value: value, + } + } + return &ColoredValue{ + ColorBytes: &fgBoldBytes, + ResetBytes: &resetBytes, + Value: value, + } + +} + +// NewColoredValueBytes creates a value from the provided value with color bytes +// If a ColoredValue is provided it is not changed +func NewColoredValueBytes(value interface{}, colorBytes *[]byte) *ColoredValue { + if val, ok := value.(*ColoredValue); ok { + return val + } + return &ColoredValue{ + ColorBytes: colorBytes, + ResetBytes: &resetBytes, + Value: &value, + } +} + +// Format will format the provided value and protect against ANSI spoofing within the value +func (cv *ColoredValue) Format(s fmt.State, c rune) { + s.Write([]byte(*cv.ColorBytes)) + fmt.Fprintf(&protectedANSIWriter{w: s}, fmtString(s, c), *(cv.Value)) + s.Write([]byte(*cv.ResetBytes)) +} + +func fmtString(s fmt.State, c rune) string { + var width, precision string + base := make([]byte, 0, 8) + base = append(base, '%') + for _, c := range []byte(" +-#0") { + if s.Flag(int(c)) { + base = append(base, c) + } + } + if w, ok := s.Width(); ok { + width = strconv.Itoa(w) + } + if p, ok := s.Precision(); ok { + precision = "." + strconv.Itoa(p) + } + return fmt.Sprintf("%s%s%s%c", base, width, precision, c) +} + +func init() { + for attr, from := range colorAttributeToString { + colorAttributeFromString[strings.ToLower(from)] = attr + } +} diff --git a/modules/log/conn.go b/modules/log/conn.go index edb149dfa5..d48bb4b334 100644 --- a/modules/log/conn.go +++ b/modules/log/conn.go @@ -1,4 +1,5 @@ // Copyright 2014 The Gogs Authors. All rights reserved. +// Copyright 2019 The Gitea Authors. All rights reserved. // Use of this source code is governed by a MIT-style // license that can be found in the LICENSE file. @@ -7,73 +8,60 @@ package log import ( "encoding/json" "io" - "log" "net" ) -// ConnWriter implements LoggerInterface. -// it writes messages in keep-live tcp connection. -type ConnWriter struct { - lg *log.Logger +type connWriter struct { innerWriter io.WriteCloser ReconnectOnMsg bool `json:"reconnectOnMsg"` Reconnect bool `json:"reconnect"` Net string `json:"net"` Addr string `json:"addr"` - Level int `json:"level"` -} - -// NewConn creates new ConnWrite returning as LoggerInterface. -func NewConn() LoggerInterface { - conn := new(ConnWriter) - conn.Level = TRACE - return conn } -// Init inits connection writer with json config. -// json config only need key "level". -func (cw *ConnWriter) Init(jsonconfig string) error { - return json.Unmarshal([]byte(jsonconfig), cw) +// Close the inner writer +func (i *connWriter) Close() error { + if i.innerWriter != nil { + return i.innerWriter.Close() + } + return nil } -// WriteMsg writes message in connection. -// if connection is down, try to re-connect. -func (cw *ConnWriter) WriteMsg(msg string, skip, level int) error { - if cw.Level > level { - return nil - } - if cw.neededConnectOnMsg() { - if err := cw.connect(); err != nil { - return err +// Write the data to the connection +func (i *connWriter) Write(p []byte) (int, error) { + if i.neededConnectOnMsg() { + if err := i.connect(); err != nil { + return 0, err } } - if cw.ReconnectOnMsg { - defer cw.innerWriter.Close() + if i.ReconnectOnMsg { + defer i.innerWriter.Close() } - cw.lg.Println(msg) - return nil -} -// Flush no things for this implementation -func (cw *ConnWriter) Flush() { + return i.innerWriter.Write(p) } -// Destroy destroy connection writer and close tcp listener. -func (cw *ConnWriter) Destroy() { - if cw.innerWriter == nil { - return +func (i *connWriter) neededConnectOnMsg() bool { + if i.Reconnect { + i.Reconnect = false + return true } - cw.innerWriter.Close() + + if i.innerWriter == nil { + return true + } + + return i.ReconnectOnMsg } -func (cw *ConnWriter) connect() error { - if cw.innerWriter != nil { - cw.innerWriter.Close() - cw.innerWriter = nil +func (i *connWriter) connect() error { + if i.innerWriter != nil { + i.innerWriter.Close() + i.innerWriter = nil } - conn, err := net.Dial(cw.Net, cw.Addr) + conn, err := net.Dial(i.Net, i.Addr) if err != nil { return err } @@ -82,22 +70,50 @@ func (cw *ConnWriter) connect() error { tcpConn.SetKeepAlive(true) } - cw.innerWriter = conn - cw.lg = log.New(conn, "", log.Ldate|log.Ltime) + i.innerWriter = conn return nil } -func (cw *ConnWriter) neededConnectOnMsg() bool { - if cw.Reconnect { - cw.Reconnect = false - return true - } +// ConnLogger implements LoggerProvider. +// it writes messages in keep-live tcp connection. +type ConnLogger struct { + BaseLogger + ReconnectOnMsg bool `json:"reconnectOnMsg"` + Reconnect bool `json:"reconnect"` + Net string `json:"net"` + Addr string `json:"addr"` +} - if cw.innerWriter == nil { - return true +// NewConn creates new ConnLogger returning as LoggerProvider. +func NewConn() LoggerProvider { + conn := new(ConnLogger) + conn.Level = TRACE + return conn +} + +// Init inits connection writer with json config. +// json config only need key "level". +func (log *ConnLogger) Init(jsonconfig string) error { + err := json.Unmarshal([]byte(jsonconfig), log) + if err != nil { + return err } + log.createLogger(&connWriter{ + ReconnectOnMsg: log.ReconnectOnMsg, + Reconnect: log.Reconnect, + Net: log.Net, + Addr: log.Addr, + }, log.Level) + return nil +} + +// Flush does nothing for this implementation +func (log *ConnLogger) Flush() { +} - return cw.ReconnectOnMsg +// GetName returns the default name for this implementation +func (log *ConnLogger) GetName() string { + return "conn" } func init() { diff --git a/modules/log/conn_test.go b/modules/log/conn_test.go new file mode 100644 index 0000000000..380a115d96 --- /dev/null +++ b/modules/log/conn_test.go @@ -0,0 +1,240 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "fmt" + "io/ioutil" + "net" + "strings" + "sync" + "testing" + "time" + + "github.com/stretchr/testify/assert" +) + +func listenReadAndClose(t *testing.T, l net.Listener, expected string) { + conn, err := l.Accept() + assert.NoError(t, err) + defer conn.Close() + written, err := ioutil.ReadAll(conn) + + assert.NoError(t, err) + assert.Equal(t, expected, string(written)) + return +} + +func TestConnLogger(t *testing.T) { + var written []byte + + protocol := "tcp" + address := ":3099" + + l, err := net.Listen(protocol, address) + if err != nil { + t.Fatal(err) + } + defer l.Close() + + prefix := "TestPrefix " + level := INFO + flags := LstdFlags | LUTC | Lfuncname + + logger := NewConn() + connLogger := logger.(*ConnLogger) + + logger.Init(fmt.Sprintf("{\"prefix\":\"%s\",\"level\":\"%s\",\"flags\":%d,\"reconnectOnMsg\":%t,\"reconnect\":%t,\"net\":\"%s\",\"addr\":\"%s\"}", prefix, level.String(), flags, true, true, protocol, address)) + + assert.Equal(t, flags, connLogger.Flags) + assert.Equal(t, level, connLogger.Level) + assert.Equal(t, level, logger.GetLevel()) + + location, _ := time.LoadLocation("EST") + + date := time.Date(2019, time.January, 13, 22, 3, 30, 15, location) + + dateString := date.UTC().Format("2006/01/02 15:04:05") + + event := Event{ + level: INFO, + msg: "TEST MSG", + caller: "CALLER", + filename: "FULL/FILENAME", + line: 1, + time: date, + } + expected := fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + var wg sync.WaitGroup + wg.Add(2) + go func() { + defer wg.Done() + listenReadAndClose(t, l, expected) + }() + go func() { + defer wg.Done() + err := logger.LogEvent(&event) + assert.NoError(t, err) + }() + wg.Wait() + + written = written[:0] + + event.level = WARN + expected = fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + wg.Add(2) + go func() { + defer wg.Done() + listenReadAndClose(t, l, expected) + }() + go func() { + defer wg.Done() + err := logger.LogEvent(&event) + assert.NoError(t, err) + }() + wg.Wait() + + logger.Close() +} + +func TestConnLoggerBadConfig(t *testing.T) { + logger := NewConn() + + err := logger.Init("{") + assert.Equal(t, "unexpected end of JSON input", err.Error()) + logger.Close() +} + +func TestConnLoggerCloseBeforeSend(t *testing.T) { + protocol := "tcp" + address := ":3099" + + prefix := "TestPrefix " + level := INFO + flags := LstdFlags | LUTC | Lfuncname + + logger := NewConn() + + logger.Init(fmt.Sprintf("{\"prefix\":\"%s\",\"level\":\"%s\",\"flags\":%d,\"reconnectOnMsg\":%t,\"reconnect\":%t,\"net\":\"%s\",\"addr\":\"%s\"}", prefix, level.String(), flags, false, false, protocol, address)) + logger.Close() +} + +func TestConnLoggerFailConnect(t *testing.T) { + protocol := "tcp" + address := ":3099" + + prefix := "TestPrefix " + level := INFO + flags := LstdFlags | LUTC | Lfuncname + + logger := NewConn() + + logger.Init(fmt.Sprintf("{\"prefix\":\"%s\",\"level\":\"%s\",\"flags\":%d,\"reconnectOnMsg\":%t,\"reconnect\":%t,\"net\":\"%s\",\"addr\":\"%s\"}", prefix, level.String(), flags, false, false, protocol, address)) + + assert.Equal(t, level, logger.GetLevel()) + + location, _ := time.LoadLocation("EST") + + date := time.Date(2019, time.January, 13, 22, 3, 30, 15, location) + + //dateString := date.UTC().Format("2006/01/02 15:04:05") + + event := Event{ + level: INFO, + msg: "TEST MSG", + caller: "CALLER", + filename: "FULL/FILENAME", + line: 1, + time: date, + } + + err := logger.LogEvent(&event) + assert.Error(t, err) + + logger.Close() +} + +func TestConnLoggerClose(t *testing.T) { + var written []byte + + protocol := "tcp" + address := ":3099" + + l, err := net.Listen(protocol, address) + if err != nil { + t.Fatal(err) + } + defer l.Close() + + prefix := "TestPrefix " + level := INFO + flags := LstdFlags | LUTC | Lfuncname + + logger := NewConn() + connLogger := logger.(*ConnLogger) + + logger.Init(fmt.Sprintf("{\"prefix\":\"%s\",\"level\":\"%s\",\"flags\":%d,\"reconnectOnMsg\":%t,\"reconnect\":%t,\"net\":\"%s\",\"addr\":\"%s\"}", prefix, level.String(), flags, false, false, protocol, address)) + + assert.Equal(t, flags, connLogger.Flags) + assert.Equal(t, level, connLogger.Level) + assert.Equal(t, level, logger.GetLevel()) + location, _ := time.LoadLocation("EST") + + date := time.Date(2019, time.January, 13, 22, 3, 30, 15, location) + + dateString := date.UTC().Format("2006/01/02 15:04:05") + + event := Event{ + level: INFO, + msg: "TEST MSG", + caller: "CALLER", + filename: "FULL/FILENAME", + line: 1, + time: date, + } + expected := fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + var wg sync.WaitGroup + wg.Add(2) + go func() { + defer wg.Done() + err := logger.LogEvent(&event) + assert.NoError(t, err) + logger.Close() + }() + go func() { + defer wg.Done() + listenReadAndClose(t, l, expected) + }() + wg.Wait() + + logger = NewConn() + connLogger = logger.(*ConnLogger) + + logger.Init(fmt.Sprintf("{\"prefix\":\"%s\",\"level\":\"%s\",\"flags\":%d,\"reconnectOnMsg\":%t,\"reconnect\":%t,\"net\":\"%s\",\"addr\":\"%s\"}", prefix, level.String(), flags, false, true, protocol, address)) + + assert.Equal(t, flags, connLogger.Flags) + assert.Equal(t, level, connLogger.Level) + assert.Equal(t, level, logger.GetLevel()) + + written = written[:0] + + event.level = WARN + expected = fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + wg.Add(2) + go func() { + defer wg.Done() + listenReadAndClose(t, l, expected) + }() + go func() { + defer wg.Done() + err := logger.LogEvent(&event) + assert.NoError(t, err) + logger.Close() + + }() + wg.Wait() + logger.Flush() + logger.Close() +} diff --git a/modules/log/console.go b/modules/log/console.go index 04991243fc..cf2dfa499f 100644 --- a/modules/log/console.go +++ b/modules/log/console.go @@ -1,4 +1,5 @@ // Copyright 2014 The Gogs Authors. All rights reserved. +// Copyright 2019 The Gitea Authors. All rights reserved. // Use of this source code is governed by a MIT-style // license that can be found in the LICENSE file. @@ -6,75 +7,72 @@ package log import ( "encoding/json" - "log" + "io" "os" - "runtime" ) -// Brush brush type -type Brush func(string) string +// CanColorStdout reports if we can color the Stdout +// Although we could do terminal sniffing and the like - in reality +// most tools on *nix are happy to display ansi colors. +// We will terminal sniff on Windows in console_windows.go +var CanColorStdout = true -// NewBrush create a brush according color -func NewBrush(color string) Brush { - pre := "\033[" - reset := "\033[0m" - return func(text string) string { - return pre + color + "m" + text + reset - } +// CanColorStderr reports if we can color the Stderr +var CanColorStderr = true + +type nopWriteCloser struct { + w io.WriteCloser } -var colors = []Brush{ - NewBrush("1;36"), // Trace cyan - NewBrush("1;34"), // Debug blue - NewBrush("1;32"), // Info green - NewBrush("1;33"), // Warn yellow - NewBrush("1;31"), // Error red - NewBrush("1;35"), // Critical purple - NewBrush("1;31"), // Fatal red +func (n *nopWriteCloser) Write(p []byte) (int, error) { + return n.w.Write(p) } -// ConsoleWriter implements LoggerInterface and writes messages to terminal. -type ConsoleWriter struct { - lg *log.Logger - Level int `json:"level"` +func (n *nopWriteCloser) Close() error { + return nil } -// NewConsole create ConsoleWriter returning as LoggerInterface. -func NewConsole() LoggerInterface { - return &ConsoleWriter{ - lg: log.New(os.Stdout, "", log.Ldate|log.Ltime), - Level: TRACE, - } +// ConsoleLogger implements LoggerProvider and writes messages to terminal. +type ConsoleLogger struct { + BaseLogger + Stderr bool `json:"stderr"` } -// Init inits connection writer with json config. -// json config only need key "level". -func (cw *ConsoleWriter) Init(config string) error { - return json.Unmarshal([]byte(config), cw) +// NewConsoleLogger create ConsoleLogger returning as LoggerProvider. +func NewConsoleLogger() LoggerProvider { + log := &ConsoleLogger{} + log.createLogger(&nopWriteCloser{ + w: os.Stdout, + }) + return log } -// WriteMsg writes message in console. -// if OS is windows, ignore colors. -func (cw *ConsoleWriter) WriteMsg(msg string, skip, level int) error { - if cw.Level > level { - return nil +// Init inits connection writer with json config. +// json config only need key "level". +func (log *ConsoleLogger) Init(config string) error { + err := json.Unmarshal([]byte(config), log) + if err != nil { + return err } - if runtime.GOOS == "windows" { - cw.lg.Println(msg) + if log.Stderr { + log.createLogger(&nopWriteCloser{ + w: os.Stderr, + }) } else { - cw.lg.Println(colors[level](msg)) + log.createLogger(log.out) } return nil } // Flush when log should be flushed -func (cw *ConsoleWriter) Flush() { +func (log *ConsoleLogger) Flush() { } -// Destroy when writer is destroy -func (cw *ConsoleWriter) Destroy() { +// GetName returns the default name for this implementation +func (log *ConsoleLogger) GetName() string { + return "console" } func init() { - Register("console", NewConsole) + Register("console", NewConsoleLogger) } diff --git a/modules/log/console_test.go b/modules/log/console_test.go new file mode 100644 index 0000000000..a028b5b875 --- /dev/null +++ b/modules/log/console_test.go @@ -0,0 +1,137 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "fmt" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" +) + +func TestConsoleLoggerBadConfig(t *testing.T) { + logger := NewConsoleLogger() + + err := logger.Init("{") + assert.Equal(t, "unexpected end of JSON input", err.Error()) + logger.Close() +} + +func TestConsoleLoggerMinimalConfig(t *testing.T) { + for _, level := range Levels() { + var written []byte + var closed bool + + c := CallbackWriteCloser{ + callback: func(p []byte, close bool) { + written = p + closed = close + }, + } + prefix := "" + flags := LstdFlags + + cw := NewConsoleLogger() + realCW := cw.(*ConsoleLogger) + cw.Init(fmt.Sprintf("{\"level\":\"%s\"}", level)) + nwc := realCW.out.(*nopWriteCloser) + nwc.w = c + + assert.Equal(t, flags, realCW.Flags) + assert.Equal(t, FromString(level), realCW.Level) + assert.Equal(t, FromString(level), cw.GetLevel()) + assert.Equal(t, prefix, realCW.Prefix) + assert.Equal(t, "", string(written)) + cw.Close() + assert.Equal(t, false, closed) + + } +} + +func TestConsoleLogger(t *testing.T) { + var written []byte + var closed bool + + c := CallbackWriteCloser{ + callback: func(p []byte, close bool) { + written = p + closed = close + }, + } + prefix := "TestPrefix " + level := INFO + flags := LstdFlags | LUTC | Lfuncname + + cw := NewConsoleLogger() + realCW := cw.(*ConsoleLogger) + realCW.Colorize = false + nwc := realCW.out.(*nopWriteCloser) + nwc.w = c + + cw.Init(fmt.Sprintf("{\"expression\":\"FILENAME\",\"prefix\":\"%s\",\"level\":\"%s\",\"flags\":%d}", prefix, level.String(), flags)) + + assert.Equal(t, flags, realCW.Flags) + assert.Equal(t, level, realCW.Level) + assert.Equal(t, level, cw.GetLevel()) + + location, _ := time.LoadLocation("EST") + + date := time.Date(2019, time.January, 13, 22, 3, 30, 15, location) + + dateString := date.UTC().Format("2006/01/02 15:04:05") + + event := Event{ + level: INFO, + msg: "TEST MSG", + caller: "CALLER", + filename: "FULL/FILENAME", + line: 1, + time: date, + } + + expected := fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + cw.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + event.level = DEBUG + expected = "" + cw.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + + event.level = TRACE + expected = "" + cw.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + + nonMatchEvent := Event{ + level: INFO, + msg: "TEST MSG", + caller: "CALLER", + filename: "FULL/FI_LENAME", + line: 1, + time: date, + } + event.level = INFO + expected = "" + cw.LogEvent(&nonMatchEvent) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + + event.level = WARN + expected = fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + cw.LogEvent(&event) + assert.Equal(t, expected, string(written)) + assert.Equal(t, false, closed) + written = written[:0] + + cw.Close() + assert.Equal(t, false, closed) +} diff --git a/modules/log/console_windows.go b/modules/log/console_windows.go new file mode 100644 index 0000000000..61469aacf8 --- /dev/null +++ b/modules/log/console_windows.go @@ -0,0 +1,43 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "os" + + "github.com/mattn/go-isatty" + "golang.org/x/sys/windows" +) + +func enableVTMode(console windows.Handle) bool { + mode := uint32(0) + err := windows.GetConsoleMode(console, &mode) + if err != nil { + return false + } + + // EnableVirtualTerminalProcessing is the console mode to allow ANSI code + // interpretation on the console. See: + // https://docs.microsoft.com/en-us/windows/console/setconsolemode + // It only works on windows 10. Earlier terminals will fail with an err which we will + // handle to say don't color + mode = mode | windows.ENABLE_VIRTUAL_TERMINAL_PROCESSING + err = windows.SetConsoleMode(console, mode) + return err == nil +} + +func init() { + if isatty.IsTerminal(os.Stdout.Fd()) { + CanColorStdout = enableVTMode(windows.Stdout) + } else { + CanColorStdout = isatty.IsCygwinTerminal(os.Stderr.Fd()) + } + + if isatty.IsTerminal(os.Stderr.Fd()) { + CanColorStderr = enableVTMode(windows.Stderr) + } else { + CanColorStderr = isatty.IsCygwinTerminal(os.Stderr.Fd()) + } +} diff --git a/modules/log/errors.go b/modules/log/errors.go new file mode 100644 index 0000000000..1fe54d4265 --- /dev/null +++ b/modules/log/errors.go @@ -0,0 +1,62 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import "fmt" + +// ErrTimeout represents a "Timeout" kind of error. +type ErrTimeout struct { + Name string + Provider string +} + +// IsErrTimeout checks if an error is a ErrTimeout. +func IsErrTimeout(err error) bool { + if err == nil { + return false + } + _, ok := err.(ErrTimeout) + return ok +} + +func (err ErrTimeout) Error() string { + return fmt.Sprintf("Log Timeout for %s (%s)", err.Name, err.Provider) +} + +// ErrUnknownProvider represents a "Unknown Provider" kind of error. +type ErrUnknownProvider struct { + Provider string +} + +// IsErrUnknownProvider checks if an error is a ErrUnknownProvider. +func IsErrUnknownProvider(err error) bool { + if err == nil { + return false + } + _, ok := err.(ErrUnknownProvider) + return ok +} + +func (err ErrUnknownProvider) Error() string { + return fmt.Sprintf("Unknown Log Provider \"%s\" (Was it registered?)", err.Provider) +} + +// ErrDuplicateName represents a Duplicate Name error +type ErrDuplicateName struct { + Name string +} + +// IsErrDuplicateName checks if an error is a ErrDuplicateName. +func IsErrDuplicateName(err error) bool { + if err == nil { + return false + } + _, ok := err.(ErrDuplicateName) + return ok +} + +func (err ErrDuplicateName) Error() string { + return fmt.Sprintf("Duplicate named logger: %s", err.Name) +} diff --git a/modules/log/event.go b/modules/log/event.go new file mode 100644 index 0000000000..2ec1f9587d --- /dev/null +++ b/modules/log/event.go @@ -0,0 +1,335 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "fmt" + "sync" + "time" +) + +// Event represents a logging event +type Event struct { + level Level + msg string + caller string + filename string + line int + time time.Time + stacktrace string +} + +// EventLogger represents the behaviours of a logger +type EventLogger interface { + LogEvent(event *Event) error + Close() + Flush() + GetLevel() Level + GetStacktraceLevel() Level + GetName() string +} + +// ChannelledLog represents a cached channel to a LoggerProvider +type ChannelledLog struct { + name string + provider string + queue chan *Event + loggerProvider LoggerProvider + flush chan bool + close chan bool + closed chan bool +} + +// NewChannelledLog a new logger instance with given logger provider and config. +func NewChannelledLog(name, provider, config string, bufferLength int64) (*ChannelledLog, error) { + if log, ok := providers[provider]; ok { + l := &ChannelledLog{ + queue: make(chan *Event, bufferLength), + flush: make(chan bool), + close: make(chan bool), + closed: make(chan bool), + } + l.loggerProvider = log() + if err := l.loggerProvider.Init(config); err != nil { + return nil, err + } + l.name = name + l.provider = provider + go l.Start() + return l, nil + } + return nil, ErrUnknownProvider{provider} +} + +// Start processing the ChannelledLog +func (l *ChannelledLog) Start() { + for { + select { + case event, ok := <-l.queue: + if !ok { + l.closeLogger() + return + } + l.loggerProvider.LogEvent(event) + case _, ok := <-l.flush: + if !ok { + l.closeLogger() + return + } + l.loggerProvider.Flush() + case _, _ = <-l.close: + l.closeLogger() + return + } + } +} + +// LogEvent logs an event to this ChannelledLog +func (l *ChannelledLog) LogEvent(event *Event) error { + select { + case l.queue <- event: + return nil + case <-time.After(60 * time.Second): + // We're blocked! + return ErrTimeout{ + Name: l.name, + Provider: l.provider, + } + } +} + +func (l *ChannelledLog) closeLogger() { + l.loggerProvider.Flush() + l.loggerProvider.Close() + l.closed <- true + return +} + +// Close this ChannelledLog +func (l *ChannelledLog) Close() { + l.close <- true + <-l.closed +} + +// Flush this ChannelledLog +func (l *ChannelledLog) Flush() { + l.flush <- true +} + +// GetLevel gets the level of this ChannelledLog +func (l *ChannelledLog) GetLevel() Level { + return l.loggerProvider.GetLevel() +} + +// GetStacktraceLevel gets the level of this ChannelledLog +func (l *ChannelledLog) GetStacktraceLevel() Level { + return l.loggerProvider.GetStacktraceLevel() +} + +// GetName returns the name of this ChannelledLog +func (l *ChannelledLog) GetName() string { + return l.name +} + +// MultiChannelledLog represents a cached channel to a LoggerProvider +type MultiChannelledLog struct { + name string + bufferLength int64 + queue chan *Event + mutex sync.Mutex + loggers map[string]EventLogger + flush chan bool + close chan bool + started bool + level Level + stacktraceLevel Level + closed chan bool +} + +// NewMultiChannelledLog a new logger instance with given logger provider and config. +func NewMultiChannelledLog(name string, bufferLength int64) *MultiChannelledLog { + m := &MultiChannelledLog{ + name: name, + queue: make(chan *Event, bufferLength), + flush: make(chan bool), + bufferLength: bufferLength, + loggers: make(map[string]EventLogger), + level: NONE, + stacktraceLevel: NONE, + close: make(chan bool), + closed: make(chan bool), + } + return m +} + +// AddLogger adds a logger to this MultiChannelledLog +func (m *MultiChannelledLog) AddLogger(logger EventLogger) error { + m.mutex.Lock() + name := logger.GetName() + if _, has := m.loggers[name]; has { + m.mutex.Unlock() + return ErrDuplicateName{name} + } + m.loggers[name] = logger + if logger.GetLevel() < m.level { + m.level = logger.GetLevel() + } + if logger.GetStacktraceLevel() < m.stacktraceLevel { + m.stacktraceLevel = logger.GetStacktraceLevel() + } + m.mutex.Unlock() + go m.Start() + return nil +} + +// DelLogger removes a sub logger from this MultiChannelledLog +// NB: If you delete the last sublogger this logger will simply drop +// log events +func (m *MultiChannelledLog) DelLogger(name string) bool { + m.mutex.Lock() + logger, has := m.loggers[name] + if !has { + m.mutex.Unlock() + return false + } + delete(m.loggers, name) + m.internalResetLevel() + m.mutex.Unlock() + logger.Flush() + logger.Close() + return true +} + +// GetEventLogger returns a sub logger from this MultiChannelledLog +func (m *MultiChannelledLog) GetEventLogger(name string) EventLogger { + m.mutex.Lock() + defer m.mutex.Unlock() + return m.loggers[name] +} + +// GetEventLoggerNames returns a list of names +func (m *MultiChannelledLog) GetEventLoggerNames() []string { + m.mutex.Lock() + defer m.mutex.Unlock() + var keys []string + for k := range m.loggers { + keys = append(keys, k) + } + return keys +} + +func (m *MultiChannelledLog) closeLoggers() { + m.mutex.Lock() + for _, logger := range m.loggers { + logger.Flush() + logger.Close() + } + m.mutex.Unlock() + m.closed <- true + return +} + +// Start processing the MultiChannelledLog +func (m *MultiChannelledLog) Start() { + m.mutex.Lock() + if m.started { + m.mutex.Unlock() + return + } + m.started = true + m.mutex.Unlock() + for { + select { + case event, ok := <-m.queue: + if !ok { + m.closeLoggers() + return + } + m.mutex.Lock() + for _, logger := range m.loggers { + err := logger.LogEvent(event) + if err != nil { + fmt.Println(err) + } + } + m.mutex.Unlock() + case _, ok := <-m.flush: + if !ok { + m.closeLoggers() + return + } + m.mutex.Lock() + for _, logger := range m.loggers { + logger.Flush() + } + m.mutex.Unlock() + case <-m.close: + m.closeLoggers() + return + } + } +} + +// LogEvent logs an event to this MultiChannelledLog +func (m *MultiChannelledLog) LogEvent(event *Event) error { + select { + case m.queue <- event: + return nil + case <-time.After(60 * time.Second): + // We're blocked! + return ErrTimeout{ + Name: m.name, + Provider: "MultiChannelledLog", + } + } +} + +// Close this MultiChannelledLog +func (m *MultiChannelledLog) Close() { + m.close <- true + <-m.closed +} + +// Flush this ChannelledLog +func (m *MultiChannelledLog) Flush() { + m.flush <- true +} + +// GetLevel gets the level of this MultiChannelledLog +func (m *MultiChannelledLog) GetLevel() Level { + return m.level +} + +// GetStacktraceLevel gets the level of this MultiChannelledLog +func (m *MultiChannelledLog) GetStacktraceLevel() Level { + return m.stacktraceLevel +} + +func (m *MultiChannelledLog) internalResetLevel() Level { + m.level = NONE + for _, logger := range m.loggers { + level := logger.GetLevel() + if level < m.level { + m.level = level + } + level = logger.GetStacktraceLevel() + if level < m.stacktraceLevel { + m.stacktraceLevel = level + } + } + return m.level +} + +// ResetLevel will reset the level of this MultiChannelledLog +func (m *MultiChannelledLog) ResetLevel() Level { + m.mutex.Lock() + defer m.mutex.Unlock() + return m.internalResetLevel() +} + +// GetName gets the name of this MultiChannelledLog +func (m *MultiChannelledLog) GetName() string { + return m.name +} diff --git a/modules/log/file.go b/modules/log/file.go index 38a28fc651..5c219c3910 100644 --- a/modules/log/file.go +++ b/modules/log/file.go @@ -5,10 +5,11 @@ package log import ( + "bufio" + "compress/gzip" "encoding/json" "errors" "fmt" - "log" "os" "path/filepath" "strings" @@ -16,10 +17,10 @@ import ( "time" ) -// FileLogWriter implements LoggerInterface. +// FileLogger implements LoggerProvider. // It writes messages by lines limit, file size limit, or time frequency. -type FileLogWriter struct { - *log.Logger +type FileLogger struct { + BaseLogger mw *MuxWriter // The opened file Filename string `json:"filename"` @@ -35,47 +36,57 @@ type FileLogWriter struct { Rotate bool `json:"rotate"` - startLock sync.Mutex // Only one log can write to the file + Compress bool `json:"compress"` + CompressionLevel int `json:"compressionLevel"` - Level int `json:"level"` + startLock sync.Mutex // Only one log can write to the file } // MuxWriter an *os.File writer with locker. type MuxWriter struct { - sync.Mutex - fd *os.File + mu sync.Mutex + fd *os.File + owner *FileLogger } // Write writes to os.File. -func (l *MuxWriter) Write(b []byte) (int, error) { - l.Lock() - defer l.Unlock() - return l.fd.Write(b) +func (mw *MuxWriter) Write(b []byte) (int, error) { + mw.mu.Lock() + defer mw.mu.Unlock() + mw.owner.docheck(len(b)) + return mw.fd.Write(b) +} + +// Close the internal writer +func (mw *MuxWriter) Close() error { + return mw.fd.Close() } // SetFd sets os.File in writer. -func (l *MuxWriter) SetFd(fd *os.File) { - if l.fd != nil { - l.fd.Close() +func (mw *MuxWriter) SetFd(fd *os.File) { + if mw.fd != nil { + mw.fd.Close() } - l.fd = fd -} - -// NewFileWriter create a FileLogWriter returning as LoggerInterface. -func NewFileWriter() LoggerInterface { - w := &FileLogWriter{ - Filename: "", - Maxsize: 1 << 28, //256 MB - Daily: true, - Maxdays: 7, - Rotate: true, - Level: TRACE, + mw.fd = fd +} + +// NewFileLogger create a FileLogger returning as LoggerProvider. +func NewFileLogger() LoggerProvider { + log := &FileLogger{ + Filename: "", + Maxsize: 1 << 28, //256 MB + Daily: true, + Maxdays: 7, + Rotate: true, + Compress: true, + CompressionLevel: gzip.DefaultCompression, } + log.Level = TRACE // 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 + log.mw = new(MuxWriter) + log.mw.owner = log + + return log } // Init file logger with json config. @@ -87,109 +98,131 @@ func NewFileWriter() LoggerInterface { // "maxdays":15, // "rotate":true // } -func (w *FileLogWriter) Init(config string) error { - if err := json.Unmarshal([]byte(config), w); err != nil { +func (log *FileLogger) Init(config string) error { + if err := json.Unmarshal([]byte(config), log); err != nil { return err } - if len(w.Filename) == 0 { + if len(log.Filename) == 0 { return errors.New("config must have filename") } - return w.StartLogger() + // set MuxWriter as Logger's io.Writer + log.createLogger(log.mw) + return log.StartLogger() } // StartLogger start file logger. create log file and set to locker-inside file writer. -func (w *FileLogWriter) StartLogger() error { - fd, err := w.createLogFile() +func (log *FileLogger) StartLogger() error { + fd, err := log.createLogFile() if err != nil { return err } - w.mw.SetFd(fd) - return w.initFd() + log.mw.SetFd(fd) + return log.initFd() } -func (w *FileLogWriter) docheck(size int) { - w.startLock.Lock() - defer w.startLock.Unlock() - if w.Rotate && ((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) +func (log *FileLogger) docheck(size int) { + log.startLock.Lock() + defer log.startLock.Unlock() + if log.Rotate && ((log.Maxsize > 0 && log.maxsizeCursize >= log.Maxsize) || + (log.Daily && time.Now().Day() != log.dailyOpenDate)) { + if err := log.DoRotate(); err != nil { + fmt.Fprintf(os.Stderr, "FileLogger(%q): %s\n", log.Filename, err) return } } - w.maxsizeCursize += size + log.maxsizeCursize += size } -// WriteMsg writes logger message into file. -func (w *FileLogWriter) WriteMsg(msg string, skip, 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 -} - -func (w *FileLogWriter) createLogFile() (*os.File, error) { +func (log *FileLogger) createLogFile() (*os.File, error) { // Open the log file - return os.OpenFile(w.Filename, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0660) + return os.OpenFile(log.Filename, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0660) } -func (w *FileLogWriter) initFd() error { - fd := w.mw.fd +func (log *FileLogger) initFd() error { + fd := log.mw.fd finfo, err := fd.Stat() if err != nil { return fmt.Errorf("get stat: %v", err) } - w.maxsizeCursize = int(finfo.Size()) - w.dailyOpenDate = time.Now().Day() + log.maxsizeCursize = int(finfo.Size()) + log.dailyOpenDate = time.Now().Day() return nil } // DoRotate means it need to write file in new file. // new file name like xx.log.2013-01-01.2 -func (w *FileLogWriter) DoRotate() error { - _, err := os.Lstat(w.Filename) +func (log *FileLogger) DoRotate() error { + _, err := os.Lstat(log.Filename) if err == nil { // file exists // Find the next available number num := 1 fname := "" for ; err == nil && num <= 999; num++ { - fname = w.Filename + fmt.Sprintf(".%s.%03d", time.Now().Format("2006-01-02"), num) + fname = log.Filename + fmt.Sprintf(".%s.%03d", time.Now().Format("2006-01-02"), num) _, err = os.Lstat(fname) + if log.Compress && err != nil { + _, err = os.Lstat(fname + ".gz") + } } // 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) + return fmt.Errorf("rotate: cannot find free log number to rename %s", log.Filename) } - // block Logger's io.Writer - w.mw.Lock() - defer w.mw.Unlock() - - fd := w.mw.fd + fd := log.mw.fd fd.Close() // close fd before rename // Rename the file to its newfound home - if err = os.Rename(w.Filename, fname); err != nil { + if err = os.Rename(log.Filename, fname); err != nil { return fmt.Errorf("Rotate: %v", err) } + if log.Compress { + go compressOldLogFile(fname, log.CompressionLevel) + } + // re-start logger - if err = w.StartLogger(); err != nil { + if err = log.StartLogger(); err != nil { return fmt.Errorf("Rotate StartLogger: %v", err) } - go w.deleteOldLog() + go log.deleteOldLog() } return nil } -func (w *FileLogWriter) deleteOldLog() { - dir := filepath.Dir(w.Filename) +func compressOldLogFile(fname string, compressionLevel int) error { + reader, err := os.Open(fname) + if err != nil { + return err + } + defer reader.Close() + buffer := bufio.NewReader(reader) + fw, err := os.OpenFile(fname+".gz", os.O_WRONLY|os.O_CREATE, 0660) + if err != nil { + return err + } + defer fw.Close() + zw, err := gzip.NewWriterLevel(fw, compressionLevel) + if err != nil { + return err + } + defer zw.Close() + _, err = buffer.WriteTo(zw) + if err != nil { + zw.Close() + fw.Close() + os.Remove(fname + ".gz") + return err + } + reader.Close() + return os.Remove(fname) +} + +func (log *FileLogger) deleteOldLog() { + dir := filepath.Dir(log.Filename) filepath.Walk(dir, func(path string, info os.FileInfo, err error) (returnErr error) { defer func() { if r := recover(); r != nil { @@ -197,8 +230,8 @@ func (w *FileLogWriter) deleteOldLog() { } }() - if !info.IsDir() && info.ModTime().Unix() < (time.Now().Unix()-60*60*24*w.Maxdays) { - if strings.HasPrefix(filepath.Base(path), filepath.Base(w.Filename)) { + if !info.IsDir() && info.ModTime().Unix() < (time.Now().Unix()-60*60*24*log.Maxdays) { + if strings.HasPrefix(filepath.Base(path), filepath.Base(log.Filename)) { if err := os.Remove(path); err != nil { returnErr = fmt.Errorf("Failed to remove %s: %v", path, err) @@ -209,18 +242,18 @@ func (w *FileLogWriter) deleteOldLog() { }) } -// Destroy destroy file logger, close file writer. -func (w *FileLogWriter) Destroy() { - w.mw.fd.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() +func (log *FileLogger) Flush() { + log.mw.fd.Sync() +} + +// GetName returns the default name for this implementation +func (log *FileLogger) GetName() string { + return "file" } func init() { - Register("file", NewFileWriter) + Register("file", NewFileLogger) } diff --git a/modules/log/file_test.go b/modules/log/file_test.go new file mode 100644 index 0000000000..9527069079 --- /dev/null +++ b/modules/log/file_test.go @@ -0,0 +1,247 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "compress/gzip" + "fmt" + "io/ioutil" + "os" + "path/filepath" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" +) + +func TestFileLoggerFails(t *testing.T) { + tmpDir, err := ioutil.TempDir("", "TestFileLogger") + assert.NoError(t, err) + defer os.RemoveAll(tmpDir) + + prefix := "TestPrefix " + level := INFO + flags := LstdFlags | LUTC | Lfuncname + //filename := filepath.Join(tmpDir, "test.log") + + fileLogger := NewFileLogger() + //realFileLogger, ok := fileLogger.(*FileLogger) + //assert.Equal(t, true, ok) + + // Fail if there is bad json + err = fileLogger.Init("{") + assert.Error(t, err) + + // Fail if there is no filename + err = fileLogger.Init(fmt.Sprintf("{\"prefix\":\"%s\",\"level\":\"%s\",\"flags\":%d,\"filename\":\"%s\"}", prefix, level.String(), flags, "")) + assert.Error(t, err) + + // Fail if the file isn't a filename + err = fileLogger.Init(fmt.Sprintf("{\"prefix\":\"%s\",\"level\":\"%s\",\"flags\":%d,\"filename\":\"%s\"}", prefix, level.String(), flags, filepath.ToSlash(tmpDir))) + assert.Error(t, err) + +} + +func TestFileLogger(t *testing.T) { + tmpDir, err := ioutil.TempDir("", "TestFileLogger") + assert.NoError(t, err) + defer os.RemoveAll(tmpDir) + + prefix := "TestPrefix " + level := INFO + flags := LstdFlags | LUTC | Lfuncname + filename := filepath.Join(tmpDir, "test.log") + + fileLogger := NewFileLogger() + realFileLogger, ok := fileLogger.(*FileLogger) + assert.Equal(t, true, ok) + + location, _ := time.LoadLocation("EST") + + date := time.Date(2019, time.January, 13, 22, 3, 30, 15, location) + + dateString := date.UTC().Format("2006/01/02 15:04:05") + + event := Event{ + level: INFO, + msg: "TEST MSG", + caller: "CALLER", + filename: "FULL/FILENAME", + line: 1, + time: date, + } + + expected := fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + + fileLogger.Init(fmt.Sprintf("{\"prefix\":\"%s\",\"level\":\"%s\",\"flags\":%d,\"filename\":\"%s\",\"maxsize\":%d,\"compress\":false}", prefix, level.String(), flags, filepath.ToSlash(filename), len(expected)*2)) + + assert.Equal(t, flags, realFileLogger.Flags) + assert.Equal(t, level, realFileLogger.Level) + assert.Equal(t, level, fileLogger.GetLevel()) + + fileLogger.LogEvent(&event) + fileLogger.Flush() + logData, err := ioutil.ReadFile(filename) + assert.NoError(t, err) + assert.Equal(t, expected, string(logData)) + + event.level = DEBUG + expected = expected + "" + fileLogger.LogEvent(&event) + fileLogger.Flush() + logData, err = ioutil.ReadFile(filename) + assert.NoError(t, err) + assert.Equal(t, expected, string(logData)) + + event.level = TRACE + expected = expected + "" + fileLogger.LogEvent(&event) + fileLogger.Flush() + logData, err = ioutil.ReadFile(filename) + assert.NoError(t, err) + assert.Equal(t, expected, string(logData)) + + event.level = WARN + expected = expected + fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + fileLogger.LogEvent(&event) + fileLogger.Flush() + logData, err = ioutil.ReadFile(filename) + assert.NoError(t, err) + assert.Equal(t, expected, string(logData)) + + // Should rotate + fileLogger.LogEvent(&event) + fileLogger.Flush() + logData, err = ioutil.ReadFile(filename + fmt.Sprintf(".%s.%03d", time.Now().Format("2006-01-02"), 1)) + assert.NoError(t, err) + assert.Equal(t, expected, string(logData)) + + logData, err = ioutil.ReadFile(filename) + assert.NoError(t, err) + expected = fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + assert.Equal(t, expected, string(logData)) + + for num := 2; num <= 999; num++ { + file, err := os.OpenFile(filename+fmt.Sprintf(".%s.%03d", time.Now().Format("2006-01-02"), num), os.O_RDONLY|os.O_CREATE, 0666) + assert.NoError(t, err) + file.Close() + } + err = realFileLogger.DoRotate() + assert.Error(t, err) + + expected = expected + fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + fileLogger.LogEvent(&event) + fileLogger.Flush() + logData, err = ioutil.ReadFile(filename) + assert.NoError(t, err) + assert.Equal(t, expected, string(logData)) + + // Should fail to rotate + expected = expected + fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + fileLogger.LogEvent(&event) + fileLogger.Flush() + logData, err = ioutil.ReadFile(filename) + assert.NoError(t, err) + assert.Equal(t, expected, string(logData)) + + fileLogger.Close() +} + +func TestCompressFileLogger(t *testing.T) { + tmpDir, err := ioutil.TempDir("", "TestFileLogger") + assert.NoError(t, err) + defer os.RemoveAll(tmpDir) + + prefix := "TestPrefix " + level := INFO + flags := LstdFlags | LUTC | Lfuncname + filename := filepath.Join(tmpDir, "test.log") + + fileLogger := NewFileLogger() + realFileLogger, ok := fileLogger.(*FileLogger) + assert.Equal(t, true, ok) + + location, _ := time.LoadLocation("EST") + + date := time.Date(2019, time.January, 13, 22, 3, 30, 15, location) + + dateString := date.UTC().Format("2006/01/02 15:04:05") + + event := Event{ + level: INFO, + msg: "TEST MSG", + caller: "CALLER", + filename: "FULL/FILENAME", + line: 1, + time: date, + } + + expected := fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + + fileLogger.Init(fmt.Sprintf("{\"prefix\":\"%s\",\"level\":\"%s\",\"flags\":%d,\"filename\":\"%s\",\"maxsize\":%d,\"compress\":true}", prefix, level.String(), flags, filepath.ToSlash(filename), len(expected)*2)) + + fileLogger.LogEvent(&event) + fileLogger.Flush() + logData, err := ioutil.ReadFile(filename) + assert.NoError(t, err) + assert.Equal(t, expected, string(logData)) + + event.level = WARN + expected = expected + fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + fileLogger.LogEvent(&event) + fileLogger.Flush() + logData, err = ioutil.ReadFile(filename) + assert.NoError(t, err) + assert.Equal(t, expected, string(logData)) + + // Should rotate + fileLogger.LogEvent(&event) + fileLogger.Flush() + + for num := 2; num <= 999; num++ { + file, err := os.OpenFile(filename+fmt.Sprintf(".%s.%03d.gz", time.Now().Format("2006-01-02"), num), os.O_RDONLY|os.O_CREATE, 0666) + assert.NoError(t, err) + file.Close() + } + err = realFileLogger.DoRotate() + assert.Error(t, err) +} + +func TestCompressOldFile(t *testing.T) { + tmpDir, err := ioutil.TempDir("", "TestFileLogger") + assert.NoError(t, err) + defer os.RemoveAll(tmpDir) + fname := filepath.Join(tmpDir, "test") + nonGzip := filepath.Join(tmpDir, "test-nonGzip") + + f, err := os.OpenFile(fname, os.O_CREATE|os.O_WRONLY, 0660) + assert.NoError(t, err) + ng, err := os.OpenFile(nonGzip, os.O_CREATE|os.O_WRONLY, 0660) + assert.NoError(t, err) + + for i := 0; i < 999; i++ { + f.WriteString("This is a test file\n") + ng.WriteString("This is a test file\n") + } + f.Close() + ng.Close() + + err = compressOldLogFile(fname, -1) + assert.NoError(t, err) + + _, err = os.Lstat(fname + ".gz") + assert.NoError(t, err) + + f, err = os.Open(fname + ".gz") + assert.NoError(t, err) + zr, err := gzip.NewReader(f) + assert.NoError(t, err) + data, err := ioutil.ReadAll(zr) + assert.NoError(t, err) + original, err := ioutil.ReadFile(nonGzip) + assert.NoError(t, err) + assert.Equal(t, original, data) +} diff --git a/modules/log/level.go b/modules/log/level.go new file mode 100644 index 0000000000..6131fcb510 --- /dev/null +++ b/modules/log/level.go @@ -0,0 +1,111 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "bytes" + "encoding/json" + "fmt" + "os" + "strings" +) + +// Level is the level of the logger +type Level int + +const ( + // TRACE represents the lowest log level + TRACE Level = iota + // DEBUG is for debug logging + DEBUG + // INFO is for information + INFO + // WARN is for warning information + WARN + // ERROR is for error reporting + ERROR + // CRITICAL is for critical errors + CRITICAL + // FATAL is for fatal errors + FATAL + // NONE is for no logging + NONE +) + +var toString = map[Level]string{ + TRACE: "trace", + DEBUG: "debug", + INFO: "info", + WARN: "warn", + ERROR: "error", + CRITICAL: "critical", + FATAL: "fatal", + NONE: "none", +} + +var toLevel = map[string]Level{ + "trace": TRACE, + "debug": DEBUG, + "info": INFO, + "warn": WARN, + "error": ERROR, + "critical": CRITICAL, + "fatal": FATAL, + "none": NONE, +} + +// Levels returns all the possible logging levels +func Levels() []string { + keys := make([]string, 0) + for key := range toLevel { + keys = append(keys, key) + } + return keys +} + +func (l Level) String() string { + s, ok := toString[l] + if ok { + return s + } + return "info" +} + +// MarshalJSON takes a Level and turns it into text +func (l Level) MarshalJSON() ([]byte, error) { + buffer := bytes.NewBufferString(`"`) + buffer.WriteString(toString[l]) + buffer.WriteString(`"`) + return buffer.Bytes(), nil +} + +// FromString takes a level string and returns a Level +func FromString(level string) Level { + temp, ok := toLevel[strings.ToLower(level)] + if !ok { + return INFO + } + return temp +} + +// UnmarshalJSON takes text and turns it into a Level +func (l *Level) UnmarshalJSON(b []byte) error { + var tmp interface{} + err := json.Unmarshal(b, &tmp) + if err != nil { + fmt.Fprintf(os.Stderr, "Err: %v", err) + return err + } + + switch v := tmp.(type) { + case string: + *l = FromString(string(v)) + case int: + *l = FromString(Level(v).String()) + default: + *l = INFO + } + return nil +} diff --git a/modules/log/level_test.go b/modules/log/level_test.go new file mode 100644 index 0000000000..40f6310bfd --- /dev/null +++ b/modules/log/level_test.go @@ -0,0 +1,55 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "encoding/json" + "fmt" + "testing" + + "github.com/stretchr/testify/assert" +) + +type testLevel struct { + Level Level `json:"level"` +} + +func TestLevelMarshalUnmarshalJSON(t *testing.T) { + levelBytes, err := json.Marshal(testLevel{ + Level: INFO, + }) + assert.NoError(t, err) + assert.Equal(t, string(makeTestLevelBytes(INFO.String())), string(levelBytes)) + + var testLevel testLevel + err = json.Unmarshal(levelBytes, &testLevel) + assert.NoError(t, err) + assert.Equal(t, INFO, testLevel.Level) + + err = json.Unmarshal(makeTestLevelBytes(`FOFOO`), &testLevel) + assert.NoError(t, err) + assert.Equal(t, INFO, testLevel.Level) + + err = json.Unmarshal([]byte(fmt.Sprintf(`{"level":%d}`, 2)), &testLevel) + assert.NoError(t, err) + assert.Equal(t, INFO, testLevel.Level) + + err = json.Unmarshal([]byte(fmt.Sprintf(`{"level":%d}`, 10012)), &testLevel) + assert.NoError(t, err) + assert.Equal(t, INFO, testLevel.Level) + + err = json.Unmarshal([]byte(`{"level":{}}`), &testLevel) + assert.NoError(t, err) + assert.Equal(t, INFO, testLevel.Level) + + assert.Equal(t, INFO.String(), Level(1001).String()) + + err = json.Unmarshal([]byte(`{"level":{}`), &testLevel.Level) + assert.Error(t, err) +} + +func makeTestLevelBytes(level string) []byte { + return []byte(fmt.Sprintf(`{"level":"%s"}`, level)) +} diff --git a/modules/log/log.go b/modules/log/log.go index 98a8014b51..c0fd117967 100644 --- a/modules/log/log.go +++ b/modules/log/log.go @@ -8,48 +8,68 @@ import ( "fmt" "os" "path" - "path/filepath" "runtime" "strings" - - "golang.org/x/sync/syncmap" ) var ( - loggers []*Logger + // DEFAULT is the name of the default logger + DEFAULT = "default" + // NamedLoggers map of named loggers + NamedLoggers = make(map[string]*Logger) // GitLogger logger for git GitLogger *Logger + prefix string ) -// NewLogger create a logger -func NewLogger(bufLen int64, mode, config string) { - logger := newLogger(bufLen) - - isExist := false - for i, l := range loggers { - if l.adapter == mode { - isExist = true - loggers[i] = logger - } +// NewLogger create a logger for the default logger +func NewLogger(bufLen int64, name, provider, config string) *Logger { + err := NewNamedLogger(DEFAULT, bufLen, name, provider, config) + if err != nil { + CriticalWithSkip(1, "Unable to create default logger: %v", err) + panic(err) } - if !isExist { - loggers = append(loggers, logger) + return NamedLoggers[DEFAULT] +} + +// NewNamedLogger creates a new named logger for a given configuration +func NewNamedLogger(name string, bufLen int64, subname, provider, config string) error { + logger, ok := NamedLoggers[name] + if !ok { + logger = newLogger(name, bufLen) + + NamedLoggers[name] = logger } - if err := logger.SetLogger(mode, config); err != nil { - Fatal(2, "Failed to set logger (%s): %v", mode, err) + + return logger.SetLogger(subname, provider, config) +} + +// DelNamedLogger closes and deletes the named logger +func DelNamedLogger(name string) { + l, ok := NamedLoggers[name] + if ok { + delete(NamedLoggers, name) + l.Close() } } -// DelLogger removes loggers that are for the given mode -func DelLogger(mode string) error { - for _, l := range loggers { - if _, ok := l.outputs.Load(mode); ok { - return l.DelLogger(mode) - } +// DelLogger removes the named sublogger from the default logger +func DelLogger(name string) error { + logger := NamedLoggers[DEFAULT] + found, err := logger.DelLogger(name) + if !found { + Trace("Log %s not found, no need to delete", name) } + return err +} - Trace("Log adapter %s not found, no need to delete", mode) - return nil +// GetLogger returns either a named logger or the default logger +func GetLogger(name string) *Logger { + logger, ok := NamedLoggers[name] + if ok { + return logger + } + return NamedLoggers[DEFAULT] } // NewGitLogger create a logger for git @@ -58,333 +78,168 @@ func NewGitLogger(logPath string) { path := path.Dir(logPath) if err := os.MkdirAll(path, os.ModePerm); err != nil { - Fatal(4, "Failed to create dir %s: %v", path, err) + Fatal("Failed to create dir %s: %v", path, err) } - GitLogger = newLogger(0) - GitLogger.SetLogger("file", fmt.Sprintf(`{"level":0,"filename":"%s","rotate":false}`, logPath)) + GitLogger = newLogger("git", 0) + GitLogger.SetLogger("file", "file", fmt.Sprintf(`{"level":"TRACE","filename":"%s","rotate":false}`, logPath)) +} + +// GetLevel returns the minimum logger level +func GetLevel() Level { + return NamedLoggers[DEFAULT].GetLevel() +} + +// GetStacktraceLevel returns the minimum logger level +func GetStacktraceLevel() Level { + return NamedLoggers[DEFAULT].GetStacktraceLevel() } // Trace records trace log func Trace(format string, v ...interface{}) { - for _, logger := range loggers { - logger.Trace(format, v...) - } + Log(1, TRACE, format, v...) +} + +// IsTrace returns true if at least one logger is TRACE +func IsTrace() bool { + return GetLevel() <= TRACE } // Debug records debug log func Debug(format string, v ...interface{}) { - for _, logger := range loggers { - logger.Debug(format, v...) - } + Log(1, DEBUG, format, v...) } -// Info records info log -func Info(format string, v ...interface{}) { - for _, logger := range loggers { - logger.Info(format, v...) - } +// IsDebug returns true if at least one logger is DEBUG +func IsDebug() bool { + return GetLevel() <= DEBUG } -// Warn records warning log -func Warn(format string, v ...interface{}) { - for _, logger := range loggers { - logger.Warn(format, v...) - } +// Info records info log +func Info(format string, v ...interface{}) { + Log(1, INFO, format, v...) } -// Error records error log -func Error(skip int, format string, v ...interface{}) { - for _, logger := range loggers { - logger.Error(skip, format, v...) - } +// IsInfo returns true if at least one logger is INFO +func IsInfo() bool { + return GetLevel() <= INFO } -// Critical records critical log -func Critical(skip int, format string, v ...interface{}) { - for _, logger := range loggers { - logger.Critical(skip, format, v...) - } +// Warn records warning log +func Warn(format string, v ...interface{}) { + Log(1, WARN, format, v...) } -// Fatal records error log and exit process -func Fatal(skip int, format string, v ...interface{}) { - Error(skip, format, v...) - for _, l := range loggers { - l.Close() - } - os.Exit(1) +// IsWarn returns true if at least one logger is WARN +func IsWarn() bool { + return GetLevel() <= WARN } -// Close closes all the loggers -func Close() { - for _, l := range loggers { - l.Close() - } +// Error records error log +func Error(format string, v ...interface{}) { + Log(1, ERROR, format, v...) } -// .___ __ _____ -// | | _____/ |_ ____________/ ____\____ ____ ____ -// | |/ \ __\/ __ \_ __ \ __\\__ \ _/ ___\/ __ \ -// | | | \ | \ ___/| | \/| | / __ \\ \__\ ___/ -// |___|___| /__| \___ >__| |__| (____ /\___ >___ > -// \/ \/ \/ \/ \/ - -// LogLevel level type for log -//type LogLevel int - -// log levels -const ( - TRACE = iota - DEBUG - INFO - WARN - ERROR - CRITICAL - FATAL -) - -// LoggerInterface represents behaviors of a logger provider. -type LoggerInterface interface { - Init(config string) error - WriteMsg(msg string, skip, level int) error - Destroy() - Flush() +// ErrorWithSkip records error log from "skip" calls back from this function +func ErrorWithSkip(skip int, format string, v ...interface{}) { + Log(skip+1, ERROR, format, v...) } -type loggerType func() LoggerInterface - -// LoggerAsWriter is a io.Writer shim around the gitea log -type LoggerAsWriter struct { - level int +// IsError returns true if at least one logger is ERROR +func IsError() bool { + return GetLevel() <= ERROR } -// NewLoggerAsWriter creates a Writer representation of the logger with setable log level -func NewLoggerAsWriter(level string) *LoggerAsWriter { - l := &LoggerAsWriter{} - switch strings.ToUpper(level) { - case "TRACE": - l.level = TRACE - case "DEBUG": - l.level = DEBUG - case "INFO": - l.level = INFO - case "WARN": - l.level = WARN - case "ERROR": - l.level = ERROR - case "CRITICAL": - l.level = CRITICAL - case "FATAL": - l.level = FATAL - default: - l.level = INFO - } - return l +// Critical records critical log +func Critical(format string, v ...interface{}) { + Log(1, CRITICAL, format, v...) } -// Write implements the io.Writer interface to allow spoofing of macaron -func (l *LoggerAsWriter) Write(p []byte) (int, error) { - l.Log(string(p)) - return len(p), nil +// CriticalWithSkip records critical log from "skip" calls back from this function +func CriticalWithSkip(skip int, format string, v ...interface{}) { + Log(skip+1, CRITICAL, format, v...) } -// Log takes a given string and logs it at the set log-level -func (l *LoggerAsWriter) Log(msg string) { - for _, logger := range loggers { - logger.writerMsg(0, l.level, msg) - } +// IsCritical returns true if at least one logger is CRITICAL +func IsCritical() bool { + return GetLevel() <= CRITICAL } -var adapters = make(map[string]loggerType) - -// Register registers given logger provider to adapters. -func Register(name string, log loggerType) { - if log == nil { - panic("log: register provider is nil") - } - if _, dup := adapters[name]; dup { - panic("log: register called twice for provider \"" + name + "\"") - } - adapters[name] = log +// Fatal records fatal log and exit process +func Fatal(format string, v ...interface{}) { + Log(1, FATAL, format, v...) + Close() + os.Exit(1) } -type logMsg struct { - skip, level int - msg string +// FatalWithSkip records fatal log from "skip" calls back from this function +func FatalWithSkip(skip int, format string, v ...interface{}) { + Log(skip+1, FATAL, format, v...) + Close() + os.Exit(1) } -// Logger is default logger in beego application. -// it can contain several providers and log message into all providers. -type Logger struct { - adapter string - level int - msg chan *logMsg - outputs syncmap.Map - quit chan bool +// IsFatal returns true if at least one logger is FATAL +func IsFatal() bool { + return GetLevel() <= FATAL } -// newLogger initializes and returns a new logger. -func newLogger(buffer int64) *Logger { - l := &Logger{ - msg: make(chan *logMsg, buffer), - quit: make(chan bool), +// Close closes all the loggers +func Close() { + l, ok := NamedLoggers[DEFAULT] + if !ok { + return } - go l.StartLogger() - return l + delete(NamedLoggers, DEFAULT) + l.Close() } -// SetLogger sets new logger instance with given logger adapter and config. -func (l *Logger) SetLogger(adapter string, config string) error { - if log, ok := adapters[adapter]; ok { - lg := log() - if err := lg.Init(config); err != nil { - return err - } - l.outputs.Store(adapter, lg) - l.adapter = adapter - } else { - panic("log: unknown adapter \"" + adapter + "\" (forgotten register?)") +// Log a message with defined skip and at logging level +// A skip of 0 refers to the caller of this command +func Log(skip int, level Level, format string, v ...interface{}) { + l, ok := NamedLoggers[DEFAULT] + if ok { + l.Log(skip+1, level, format, v...) } - return nil } -// DelLogger removes a logger adapter instance. -func (l *Logger) DelLogger(adapter string) error { - if lg, ok := l.outputs.Load(adapter); ok { - lg.(LoggerInterface).Destroy() - l.outputs.Delete(adapter) - } else { - panic("log: unknown adapter \"" + adapter + "\" (forgotten register?)") - } - return nil +// LoggerAsWriter is a io.Writer shim around the gitea log +type LoggerAsWriter struct { + ourLoggers []*Logger + level Level } -func (l *Logger) writerMsg(skip, level int, msg string) error { - if l.level > level { - return nil - } - lm := &logMsg{ - skip: skip, - level: level, - } - - // Only error information needs locate position for debugging. - if lm.level >= ERROR { - pc, file, line, ok := runtime.Caller(skip) - if ok { - // Get caller function name. - fn := runtime.FuncForPC(pc) - var fnName string - if fn == nil { - fnName = "?()" - } else { - fnName = strings.TrimLeft(filepath.Ext(fn.Name()), ".") + "()" - } - - fileName := file - if len(fileName) > 20 { - fileName = "..." + fileName[len(fileName)-20:] - } - lm.msg = fmt.Sprintf("[%s:%d %s] %s", fileName, line, fnName, msg) - } else { - lm.msg = msg - } - } else { - lm.msg = msg +// NewLoggerAsWriter creates a Writer representation of the logger with setable log level +func NewLoggerAsWriter(level string, ourLoggers ...*Logger) *LoggerAsWriter { + if len(ourLoggers) == 0 { + ourLoggers = []*Logger{NamedLoggers[DEFAULT]} } - l.msg <- lm - return nil -} - -// StartLogger starts logger chan reading. -func (l *Logger) StartLogger() { - for { - select { - case bm := <-l.msg: - l.outputs.Range(func(k, v interface{}) bool { - if err := v.(LoggerInterface).WriteMsg(bm.msg, bm.skip, bm.level); err != nil { - fmt.Println("ERROR, unable to WriteMsg:", err) - } - return true - }) - case <-l.quit: - return - } + l := &LoggerAsWriter{ + ourLoggers: ourLoggers, + level: FromString(level), } + return l } -// Flush flushes all chan data. -func (l *Logger) Flush() { - l.outputs.Range(func(k, v interface{}) bool { - v.(LoggerInterface).Flush() - return true - }) -} - -// Close closes logger, flush all chan data and destroy all adapter instances. -func (l *Logger) Close() { - l.quit <- true - for { - if len(l.msg) > 0 { - bm := <-l.msg - l.outputs.Range(func(k, v interface{}) bool { - if err := v.(LoggerInterface).WriteMsg(bm.msg, bm.skip, bm.level); err != nil { - fmt.Println("ERROR, unable to WriteMsg:", err) - } - return true - }) - } else { - break - } +// Write implements the io.Writer interface to allow spoofing of macaron +func (l *LoggerAsWriter) Write(p []byte) (int, error) { + for _, logger := range l.ourLoggers { + // Skip = 3 because this presumes that we have been called by log.Println() + // If the caller has used log.Output or the like this will be wrong + logger.Log(3, l.level, string(p)) } - l.outputs.Range(func(k, v interface{}) bool { - v.(LoggerInterface).Flush() - v.(LoggerInterface).Destroy() - return true - }) -} - -// Trace records trace log -func (l *Logger) Trace(format string, v ...interface{}) { - msg := fmt.Sprintf("[T] "+format, v...) - l.writerMsg(0, TRACE, msg) -} - -// Debug records debug log -func (l *Logger) Debug(format string, v ...interface{}) { - msg := fmt.Sprintf("[D] "+format, v...) - l.writerMsg(0, DEBUG, msg) -} - -// Info records information log -func (l *Logger) Info(format string, v ...interface{}) { - msg := fmt.Sprintf("[I] "+format, v...) - l.writerMsg(0, INFO, msg) -} - -// Warn records warning log -func (l *Logger) Warn(format string, v ...interface{}) { - msg := fmt.Sprintf("[W] "+format, v...) - l.writerMsg(0, WARN, msg) -} - -// Error records error log -func (l *Logger) Error(skip int, format string, v ...interface{}) { - msg := fmt.Sprintf("[E] "+format, v...) - l.writerMsg(skip, ERROR, msg) + return len(p), nil } -// Critical records critical log -func (l *Logger) Critical(skip int, format string, v ...interface{}) { - msg := fmt.Sprintf("[C] "+format, v...) - l.writerMsg(skip, CRITICAL, msg) +// Log takes a given string and logs it at the set log-level +func (l *LoggerAsWriter) Log(msg string) { + for _, logger := range l.ourLoggers { + // Set the skip to reference the call just above this + logger.Log(1, l.level, msg) + } } -// Fatal records error log and exit the process -func (l *Logger) Fatal(skip int, format string, v ...interface{}) { - msg := fmt.Sprintf("[F] "+format, v...) - l.writerMsg(skip, FATAL, msg) - l.Close() - os.Exit(1) +func init() { + _, filename, _, _ := runtime.Caller(0) + prefix = strings.TrimSuffix(filename, "modules/log/log.go") } diff --git a/modules/log/log_test.go b/modules/log/log_test.go new file mode 100644 index 0000000000..9e3d7527b2 --- /dev/null +++ b/modules/log/log_test.go @@ -0,0 +1,154 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "fmt" + "testing" + + "github.com/stretchr/testify/assert" +) + +func baseConsoleTest(t *testing.T, logger *Logger) (chan []byte, chan bool) { + written := make(chan []byte) + closed := make(chan bool) + + c := CallbackWriteCloser{ + callback: func(p []byte, close bool) { + written <- p + closed <- close + }, + } + m := logger.MultiChannelledLog + + channelledLog := m.GetEventLogger("console") + assert.NotEmpty(t, channelledLog) + realChanLog, ok := channelledLog.(*ChannelledLog) + assert.Equal(t, true, ok) + realCL, ok := realChanLog.loggerProvider.(*ConsoleLogger) + assert.Equal(t, true, ok) + assert.Equal(t, INFO, realCL.Level) + realCL.out = c + + format := "test: %s" + args := []interface{}{"A"} + + logger.Log(0, INFO, format, args...) + line := <-written + assert.Contains(t, string(line), fmt.Sprintf(format, args...)) + assert.Equal(t, false, <-closed) + + format = "test2: %s" + logger.Warn(format, args...) + line = <-written + + assert.Contains(t, string(line), fmt.Sprintf(format, args...)) + assert.Equal(t, false, <-closed) + + format = "testerror: %s" + logger.Error(format, args...) + line = <-written + assert.Contains(t, string(line), fmt.Sprintf(format, args...)) + assert.Equal(t, false, <-closed) + return written, closed +} + +func TestNewLoggerUnexported(t *testing.T) { + level := INFO + logger := newLogger("UNEXPORTED", 0) + err := logger.SetLogger("console", "console", fmt.Sprintf(`{"level":"%s"}`, level.String())) + assert.NoError(t, err) + out := logger.MultiChannelledLog.GetEventLogger("console") + assert.NotEmpty(t, out) + chanlog, ok := out.(*ChannelledLog) + assert.Equal(t, true, ok) + assert.Equal(t, "console", chanlog.provider) + assert.Equal(t, INFO, logger.GetLevel()) + baseConsoleTest(t, logger) +} + +func TestNewLoggger(t *testing.T) { + level := INFO + logger := NewLogger(0, "console", "console", fmt.Sprintf(`{"level":"%s"}`, level.String())) + + assert.Equal(t, INFO, GetLevel()) + assert.Equal(t, false, IsTrace()) + assert.Equal(t, false, IsDebug()) + assert.Equal(t, true, IsInfo()) + assert.Equal(t, true, IsWarn()) + assert.Equal(t, true, IsError()) + + written, closed := baseConsoleTest(t, logger) + + format := "test: %s" + args := []interface{}{"A"} + + Log(0, INFO, format, args...) + line := <-written + assert.Contains(t, string(line), fmt.Sprintf(format, args...)) + assert.Equal(t, false, <-closed) + + Info(format, args...) + line = <-written + assert.Contains(t, string(line), fmt.Sprintf(format, args...)) + assert.Equal(t, false, <-closed) + + go DelLogger("console") + line = <-written + assert.Equal(t, "", string(line)) + assert.Equal(t, true, <-closed) +} + +func TestNewLogggerRecreate(t *testing.T) { + level := INFO + NewLogger(0, "console", "console", fmt.Sprintf(`{"level":"%s"}`, level.String())) + + assert.Equal(t, INFO, GetLevel()) + assert.Equal(t, false, IsTrace()) + assert.Equal(t, false, IsDebug()) + assert.Equal(t, true, IsInfo()) + assert.Equal(t, true, IsWarn()) + assert.Equal(t, true, IsError()) + + format := "test: %s" + args := []interface{}{"A"} + + Log(0, INFO, format, args...) + + NewLogger(0, "console", "console", fmt.Sprintf(`{"level":"%s"}`, level.String())) + + assert.Equal(t, INFO, GetLevel()) + assert.Equal(t, false, IsTrace()) + assert.Equal(t, false, IsDebug()) + assert.Equal(t, true, IsInfo()) + assert.Equal(t, true, IsWarn()) + assert.Equal(t, true, IsError()) + + Log(0, INFO, format, args...) + + assert.Panics(t, func() { + NewLogger(0, "console", "console", fmt.Sprintf(`{"level":"%s"`, level.String())) + }) + + go DelLogger("console") + + // We should be able to redelete without a problem + go DelLogger("console") + +} + +func TestNewNamedLogger(t *testing.T) { + level := INFO + err := NewNamedLogger("test", 0, "console", "console", fmt.Sprintf(`{"level":"%s"}`, level.String())) + assert.NoError(t, err) + logger := NamedLoggers["test"] + assert.Equal(t, level, logger.GetLevel()) + + written, closed := baseConsoleTest(t, logger) + go DelNamedLogger("test") + line := <-written + assert.Equal(t, "", string(line)) + assert.Equal(t, true, <-closed) +} diff --git a/modules/log/logger.go b/modules/log/logger.go new file mode 100644 index 0000000000..925ab02b71 --- /dev/null +++ b/modules/log/logger.go @@ -0,0 +1,156 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "fmt" + "os" + "runtime" + "strings" + "time" +) + +// Logger is default logger in the Gitea application. +// it can contain several providers and log message into all providers. +type Logger struct { + *MultiChannelledLog + bufferLength int64 +} + +// newLogger initializes and returns a new logger. +func newLogger(name string, buffer int64) *Logger { + l := &Logger{ + MultiChannelledLog: NewMultiChannelledLog(name, buffer), + bufferLength: buffer, + } + return l +} + +// SetLogger sets new logger instance with given logger provider and config. +func (l *Logger) SetLogger(name, provider, config string) error { + eventLogger, err := NewChannelledLog(name, provider, config, l.bufferLength) + if err != nil { + return fmt.Errorf("Failed to create sublogger (%s): %v", name, err) + } + + l.MultiChannelledLog.DelLogger(name) + + err = l.MultiChannelledLog.AddLogger(eventLogger) + if err != nil { + if IsErrDuplicateName(err) { + return fmt.Errorf("Duplicate named sublogger %s %v", name, l.MultiChannelledLog.GetEventLoggerNames()) + } + return fmt.Errorf("Failed to add sublogger (%s): %v", name, err) + } + + return nil +} + +// DelLogger deletes a sublogger from this logger. +func (l *Logger) DelLogger(name string) (bool, error) { + return l.MultiChannelledLog.DelLogger(name), nil +} + +// Log msg at the provided level with the provided caller defined by skip (0 being the function that calls this function) +func (l *Logger) Log(skip int, level Level, format string, v ...interface{}) error { + if l.GetLevel() > level { + return nil + } + caller := "?()" + pc, filename, line, ok := runtime.Caller(skip + 1) + if ok { + // Get caller function name. + fn := runtime.FuncForPC(pc) + if fn != nil { + caller = fn.Name() + "()" + } + } + msg := format + if len(v) > 0 { + args := make([]interface{}, len(v)) + for i := 0; i < len(args); i++ { + args[i] = NewColoredValuePointer(&v[i]) + } + msg = fmt.Sprintf(format, args...) + } + stack := "" + if l.GetStacktraceLevel() <= level { + stack = Stack(skip + 1) + } + return l.SendLog(level, caller, strings.TrimPrefix(filename, prefix), line, msg, stack) +} + +// SendLog sends a log event at the provided level with the information given +func (l *Logger) SendLog(level Level, caller, filename string, line int, msg string, stack string) error { + if l.GetLevel() > level { + return nil + } + event := &Event{ + level: level, + caller: caller, + filename: filename, + line: line, + msg: msg, + time: time.Now(), + stacktrace: stack, + } + l.LogEvent(event) + return nil +} + +// Trace records trace log +func (l *Logger) Trace(format string, v ...interface{}) { + l.Log(1, TRACE, format, v...) +} + +// Debug records debug log +func (l *Logger) Debug(format string, v ...interface{}) { + l.Log(1, DEBUG, format, v...) + +} + +// Info records information log +func (l *Logger) Info(format string, v ...interface{}) { + l.Log(1, INFO, format, v...) +} + +// Warn records warning log +func (l *Logger) Warn(format string, v ...interface{}) { + l.Log(1, WARN, format, v...) +} + +// Error records error log +func (l *Logger) Error(format string, v ...interface{}) { + l.Log(1, ERROR, format, v...) +} + +// ErrorWithSkip records error log from "skip" calls back from this function +func (l *Logger) ErrorWithSkip(skip int, format string, v ...interface{}) { + l.Log(skip+1, ERROR, format, v...) +} + +// Critical records critical log +func (l *Logger) Critical(format string, v ...interface{}) { + l.Log(1, CRITICAL, format, v...) +} + +// CriticalWithSkip records critical log from "skip" calls back from this function +func (l *Logger) CriticalWithSkip(skip int, format string, v ...interface{}) { + l.Log(skip+1, CRITICAL, format, v...) +} + +// Fatal records fatal log and exit the process +func (l *Logger) Fatal(format string, v ...interface{}) { + l.Log(1, FATAL, format, v...) + l.Close() + os.Exit(1) +} + +// FatalWithSkip records fatal log from "skip" calls back from this function and exits the process +func (l *Logger) FatalWithSkip(skip int, format string, v ...interface{}) { + l.Log(skip+1, FATAL, format, v...) + l.Close() + os.Exit(1) +} diff --git a/modules/log/provider.go b/modules/log/provider.go new file mode 100644 index 0000000000..b31bf392e6 --- /dev/null +++ b/modules/log/provider.go @@ -0,0 +1,26 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +// LoggerProvider represents behaviors of a logger provider. +type LoggerProvider interface { + Init(config string) error + EventLogger +} + +type loggerProvider func() LoggerProvider + +var providers = make(map[string]loggerProvider) + +// Register registers given logger provider to providers. +func Register(name string, log loggerProvider) { + if log == nil { + panic("log: register provider is nil") + } + if _, dup := providers[name]; dup { + panic("log: register called twice for provider \"" + name + "\"") + } + providers[name] = log +} diff --git a/modules/log/router.go b/modules/log/router.go new file mode 100644 index 0000000000..842202c781 --- /dev/null +++ b/modules/log/router.go @@ -0,0 +1,103 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "net/http" + "time" + + macaron "gopkg.in/macaron.v1" +) + +var statusToColor = map[int][]byte{ + 100: ColorBytes(Bold), + 200: ColorBytes(FgGreen), + 300: ColorBytes(FgYellow), + 304: ColorBytes(FgCyan), + 400: ColorBytes(Bold, FgRed), + 401: ColorBytes(Bold, FgMagenta), + 403: ColorBytes(Bold, FgMagenta), + 500: ColorBytes(Bold, BgRed), +} + +func coloredStatus(status int, s ...string) *ColoredValue { + color, ok := statusToColor[status] + if !ok { + color, ok = statusToColor[(status/100)*100] + } + if !ok { + color = fgBoldBytes + } + if len(s) > 0 { + return NewColoredValueBytes(s[0], &color) + } + return NewColoredValueBytes(status, &color) +} + +var methodToColor = map[string][]byte{ + "GET": ColorBytes(FgBlue), + "POST": ColorBytes(FgGreen), + "DELETE": ColorBytes(FgRed), + "PATCH": ColorBytes(FgCyan), + "PUT": ColorBytes(FgYellow, Faint), + "HEAD": ColorBytes(FgBlue, Faint), +} + +func coloredMethod(method string) *ColoredValue { + color, ok := methodToColor[method] + if !ok { + return NewColoredValueBytes(method, &fgBoldBytes) + } + return NewColoredValueBytes(method, &color) +} + +var durations = []time.Duration{ + 10 * time.Millisecond, + 100 * time.Millisecond, + 1 * time.Second, + 5 * time.Second, + 10 * time.Second, +} + +var durationColors = [][]byte{ + ColorBytes(FgGreen), + ColorBytes(Bold), + ColorBytes(FgYellow), + ColorBytes(FgRed, Bold), + ColorBytes(BgRed), +} + +var wayTooLong = ColorBytes(BgMagenta) + +func coloredTime(duration time.Duration) *ColoredValue { + for i, k := range durations { + if duration < k { + return NewColoredValueBytes(duration, &durationColors[i]) + } + } + return NewColoredValueBytes(duration, &wayTooLong) +} + +// SetupRouterLogger will setup macaron to routing to the main gitea log +func SetupRouterLogger(m *macaron.Macaron, level Level) { + if GetLevel() <= level { + m.Use(RouterHandler(level)) + } +} + +// RouterHandler is a macaron handler that will log the routing to the default gitea log +func RouterHandler(level Level) func(ctx *macaron.Context) { + return func(ctx *macaron.Context) { + start := time.Now() + + GetLogger("router").Log(0, level, "Started %s %s for %s", coloredMethod(ctx.Req.Method), ctx.Req.RequestURI, ctx.RemoteAddr()) + + rw := ctx.Resp.(macaron.ResponseWriter) + ctx.Next() + + status := rw.Status() + GetLogger("router").Log(0, level, "Completed %s %s %v %s in %v", coloredMethod(ctx.Req.Method), ctx.Req.RequestURI, coloredStatus(status), coloredStatus(status, http.StatusText(rw.Status())), coloredTime(time.Since(start))) + } +} diff --git a/modules/log/smtp.go b/modules/log/smtp.go index 760b8e8bd7..2e78d713ca 100644 --- a/modules/log/smtp.go +++ b/modules/log/smtp.go @@ -1,4 +1,5 @@ // Copyright 2014 The Gogs Authors. All rights reserved. +// Copyright 2019 The Gitea Authors. All rights reserved. // Use of this source code is governed by a MIT-style // license that can be found in the LICENSE file. @@ -6,29 +7,45 @@ package log import ( "encoding/json" - "fmt" "net/smtp" "strings" - "time" ) const ( subjectPhrase = "Diagnostic message from server" ) -// SMTPWriter implements LoggerInterface and is used to send emails via given SMTP-server. -type SMTPWriter struct { +type smtpWriter struct { + owner *SMTPLogger +} + +// Write sends the message as an email +func (s *smtpWriter) Write(p []byte) (int, error) { + return s.owner.sendMail(p) +} + +// Close does nothing +func (s *smtpWriter) Close() error { + return nil +} + +// SMTPLogger implements LoggerProvider and is used to send emails via given SMTP-server. +type SMTPLogger struct { + BaseLogger Username string `json:"Username"` Password string `json:"password"` - Host string `json:"Host"` + Host string `json:"host"` Subject string `json:"subject"` RecipientAddresses []string `json:"sendTos"` - Level int `json:"level"` + sendMailFn func(string, smtp.Auth, string, []string, []byte) error } -// NewSMTPWriter creates smtp writer. -func NewSMTPWriter() LoggerInterface { - return &SMTPWriter{Level: TRACE} +// NewSMTPLogger creates smtp writer. +func NewSMTPLogger() LoggerProvider { + s := &SMTPLogger{} + s.Level = TRACE + s.sendMailFn = smtp.SendMail + return s } // Init smtp writer with json config. @@ -41,49 +58,54 @@ func NewSMTPWriter() LoggerInterface { // "sendTos":["email1","email2"], // "level":LevelError // } -func (sw *SMTPWriter) Init(jsonconfig string) error { - return json.Unmarshal([]byte(jsonconfig), sw) +func (log *SMTPLogger) Init(jsonconfig string) error { + err := json.Unmarshal([]byte(jsonconfig), log) + if err != nil { + return err + } + log.createLogger(&smtpWriter{ + owner: log, + }) + log.sendMailFn = smtp.SendMail + return nil } // WriteMsg writes message in smtp writer. // it will send an email with subject and only this message. -func (sw *SMTPWriter) WriteMsg(msg string, skip, level int) error { - if level < sw.Level { - return nil - } - - hp := strings.Split(sw.Host, ":") +func (log *SMTPLogger) sendMail(p []byte) (int, error) { + hp := strings.Split(log.Host, ":") // Set up authentication information. auth := smtp.PlainAuth( "", - sw.Username, - sw.Password, + log.Username, + log.Password, hp[0], ) // Connect to the server, authenticate, set the sender and recipient, // and send the email all in one step. contentType := "Content-Type: text/plain" + "; charset=UTF-8" - mailmsg := []byte("To: " + strings.Join(sw.RecipientAddresses, ";") + "\r\nFrom: " + sw.Username + "<" + sw.Username + - ">\r\nSubject: " + sw.Subject + "\r\n" + contentType + "\r\n\r\n" + fmt.Sprintf(".%s", time.Now().Format("2006-01-02 15:04:05")) + msg) - - return smtp.SendMail( - sw.Host, + mailmsg := []byte("To: " + strings.Join(log.RecipientAddresses, ";") + "\r\nFrom: " + log.Username + "<" + log.Username + + ">\r\nSubject: " + log.Subject + "\r\n" + contentType + "\r\n\r\n") + mailmsg = append(mailmsg, p...) + return len(p), log.sendMailFn( + log.Host, auth, - sw.Username, - sw.RecipientAddresses, + log.Username, + log.RecipientAddresses, mailmsg, ) } // Flush when log should be flushed -func (sw *SMTPWriter) Flush() { +func (log *SMTPLogger) Flush() { } -// Destroy when writer is destroy -func (sw *SMTPWriter) Destroy() { +// GetName returns the default name for this implementation +func (log *SMTPLogger) GetName() string { + return "smtp" } func init() { - Register("smtp", NewSMTPWriter) + Register("smtp", NewSMTPLogger) } diff --git a/modules/log/smtp_test.go b/modules/log/smtp_test.go new file mode 100644 index 0000000000..216d555215 --- /dev/null +++ b/modules/log/smtp_test.go @@ -0,0 +1,86 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "fmt" + "net/smtp" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" +) + +func TestSMTPLogger(t *testing.T) { + prefix := "TestPrefix " + level := INFO + flags := LstdFlags | LUTC | Lfuncname + username := "testuser" + password := "testpassword" + host := "testhost" + subject := "testsubject" + sendTos := []string{"testto1", "testto2"} + + logger := NewSMTPLogger() + smtpLogger, ok := logger.(*SMTPLogger) + assert.Equal(t, true, ok) + + err := logger.Init(fmt.Sprintf("{\"prefix\":\"%s\",\"level\":\"%s\",\"flags\":%d,\"username\":\"%s\",\"password\":\"%s\",\"host\":\"%s\",\"subject\":\"%s\",\"sendTos\":[\"%s\",\"%s\"]}", prefix, level.String(), flags, username, password, host, subject, sendTos[0], sendTos[1])) + assert.NoError(t, err) + + assert.Equal(t, flags, smtpLogger.Flags) + assert.Equal(t, level, smtpLogger.Level) + assert.Equal(t, level, logger.GetLevel()) + + location, _ := time.LoadLocation("EST") + + date := time.Date(2019, time.January, 13, 22, 3, 30, 15, location) + + dateString := date.UTC().Format("2006/01/02 15:04:05") + + event := Event{ + level: INFO, + msg: "TEST MSG", + caller: "CALLER", + filename: "FULL/FILENAME", + line: 1, + time: date, + } + + expected := fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + + var envToHost string + var envFrom string + var envTo []string + var envMsg []byte + smtpLogger.sendMailFn = func(addr string, a smtp.Auth, from string, to []string, msg []byte) error { + envToHost = addr + envFrom = from + envTo = to + envMsg = msg + return nil + } + + err = logger.LogEvent(&event) + assert.NoError(t, err) + assert.Equal(t, host, envToHost) + assert.Equal(t, username, envFrom) + assert.Equal(t, sendTos, envTo) + assert.Contains(t, string(envMsg), expected) + + logger.Flush() + + event.level = WARN + expected = fmt.Sprintf("%s%s %s:%d:%s [%c] %s\n", prefix, dateString, event.filename, event.line, event.caller, strings.ToUpper(event.level.String())[0], event.msg) + err = logger.LogEvent(&event) + assert.NoError(t, err) + assert.Equal(t, host, envToHost) + assert.Equal(t, username, envFrom) + assert.Equal(t, sendTos, envTo) + assert.Contains(t, string(envMsg), expected) + + logger.Close() +} diff --git a/modules/log/stack.go b/modules/log/stack.go new file mode 100644 index 0000000000..ffe9aa67cc --- /dev/null +++ b/modules/log/stack.go @@ -0,0 +1,83 @@ +// Copyright 2019 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package log + +import ( + "bytes" + "fmt" + "io/ioutil" + "runtime" +) + +var ( + unknown = []byte("???") +) + +// Stack will skip back the provided number of frames and return a stack trace with source code. +// Although we could just use debug.Stack(), this routine will return the source code and +// skip back the provided number of frames - i.e. allowing us to ignore preceding function calls. +// A skip of 0 returns the stack trace for the calling function, not including this call. +// If the problem is a lack of memory of course all this is not going to work... +func Stack(skip int) string { + buf := new(bytes.Buffer) + + // Store the last file we opened as its probable that the preceding stack frame + // will be in the same file + var lines [][]byte + var lastFilename string + for i := skip + 1; ; i++ { // Skip over frames + programCounter, filename, lineNumber, ok := runtime.Caller(i) + // If we can't retrieve the information break - basically we're into go internals at this point. + if !ok { + break + } + + // Print equivalent of debug.Stack() + fmt.Fprintf(buf, "%s:%d (0x%x)\n", filename, lineNumber, programCounter) + // Now try to print the offending line + if filename != lastFilename { + data, err := ioutil.ReadFile(filename) + if err != nil { + // can't read this sourcefile + // likely we don't have the sourcecode available + continue + } + lines = bytes.Split(data, []byte{'\n'}) + lastFilename = filename + } + fmt.Fprintf(buf, "\t%s: %s\n", functionName(programCounter), source(lines, lineNumber)) + } + return buf.String() +} + +// functionName converts the provided programCounter into a function name +func functionName(programCounter uintptr) []byte { + function := runtime.FuncForPC(programCounter) + if function == nil { + return unknown + } + name := []byte(function.Name()) + + // Because we provide the filename we can drop the preceding package name. + if lastslash := bytes.LastIndex(name, []byte("/")); lastslash >= 0 { + name = name[lastslash+1:] + } + // And the current package name. + if period := bytes.Index(name, []byte(".")); period >= 0 { + name = name[period+1:] + } + // And we should just replace the interpunct with a dot + name = bytes.Replace(name, []byte("ยท"), []byte("."), -1) + return name +} + +// source returns a space-trimmed slice of the n'th line. +func source(lines [][]byte, n int) []byte { + n-- // in stack trace, lines are 1-indexed but our array is 0-indexed + if n < 0 || n >= len(lines) { + return unknown + } + return bytes.TrimSpace(lines[n]) +} diff --git a/modules/log/xorm.go b/modules/log/xorm.go index 1a218a90cd..c08b7fd7d5 100644 --- a/modules/log/xorm.go +++ b/modules/log/xorm.go @@ -12,7 +12,6 @@ import ( // XORMLogBridge a logger bridge from Logger to xorm type XORMLogBridge struct { - loggers []*Logger showSQL bool level core.LogLevel } @@ -22,110 +21,80 @@ var ( XORMLogger *XORMLogBridge ) -// DiscardXORMLogger inits a blank logger for xorm -func DiscardXORMLogger() { +// InitXORMLogger inits a log bridge for xorm +func InitXORMLogger(showSQL bool) { XORMLogger = &XORMLogBridge{ - showSQL: false, + showSQL: showSQL, } } -// NewXORMLogger generate logger for xorm FIXME: configable -func NewXORMLogger(bufferlen int64, mode, config string) { - logger := newLogger(bufferlen) - logger.SetLogger(mode, config) - if XORMLogger == nil { - XORMLogger = &XORMLogBridge{ - showSQL: true, - } - } - XORMLogger.loggers = append(XORMLogger.loggers, logger) +// GetGiteaLevel returns the minimum Gitea logger level +func (l *XORMLogBridge) GetGiteaLevel() Level { + return GetLogger("xorm").GetLevel() } -func (l *XORMLogBridge) writerMsg(skip, level int, msg string) error { - for _, logger := range l.loggers { - if err := logger.writerMsg(skip, level, msg); err != nil { - return err - } - } - return nil +// Log a message with defined skip and at logging level +func (l *XORMLogBridge) Log(skip int, level Level, format string, v ...interface{}) error { + return GetLogger("xorm").Log(skip+1, level, format, v...) } // Debug show debug log func (l *XORMLogBridge) Debug(v ...interface{}) { - if l.level <= core.LOG_DEBUG { - msg := fmt.Sprint(v...) - l.writerMsg(0, DEBUG, "[D]"+msg) - } + l.Log(2, DEBUG, fmt.Sprint(v...)) } // Debugf show debug log func (l *XORMLogBridge) Debugf(format string, v ...interface{}) { - if l.level <= core.LOG_DEBUG { - for _, logger := range l.loggers { - logger.Debug(format, v...) - } - } + l.Log(2, DEBUG, format, v...) } // Error show error log func (l *XORMLogBridge) Error(v ...interface{}) { - if l.level <= core.LOG_ERR { - msg := fmt.Sprint(v...) - l.writerMsg(0, ERROR, "[E]"+msg) - } + l.Log(2, ERROR, fmt.Sprint(v...)) } // Errorf show error log func (l *XORMLogBridge) Errorf(format string, v ...interface{}) { - if l.level <= core.LOG_ERR { - for _, logger := range l.loggers { - logger.Error(0, format, v...) - } - } + l.Log(2, ERROR, format, v...) } // Info show information level log func (l *XORMLogBridge) Info(v ...interface{}) { - if l.level <= core.LOG_INFO { - msg := fmt.Sprint(v...) - l.writerMsg(0, INFO, "[I]"+msg) - } + l.Log(2, INFO, fmt.Sprint(v...)) } // Infof show information level log func (l *XORMLogBridge) Infof(format string, v ...interface{}) { - if l.level <= core.LOG_INFO { - for _, logger := range l.loggers { - logger.Info(format, v...) - } - } + l.Log(2, INFO, format, v...) } // Warn show warning log func (l *XORMLogBridge) Warn(v ...interface{}) { - if l.level <= core.LOG_WARNING { - msg := fmt.Sprint(v...) - l.writerMsg(0, WARN, "[W] "+msg) - } + l.Log(2, WARN, fmt.Sprint(v...)) } // Warnf show warnning log func (l *XORMLogBridge) Warnf(format string, v ...interface{}) { - if l.level <= core.LOG_WARNING { - for _, logger := range l.loggers { - logger.Warn(format, v...) - } - } + l.Log(2, WARN, format, v...) } // Level get logger level func (l *XORMLogBridge) Level() core.LogLevel { - return l.level + switch l.GetGiteaLevel() { + case TRACE, DEBUG: + return core.LOG_DEBUG + case INFO: + return core.LOG_INFO + case WARN: + return core.LOG_WARNING + case ERROR, CRITICAL: + return core.LOG_ERR + } + return core.LOG_OFF } -// SetLevel set logger level -func (l *XORMLogBridge) SetLevel(level core.LogLevel) { - l.level = level +// SetLevel set the logger level +func (l *XORMLogBridge) SetLevel(lvl core.LogLevel) { } // ShowSQL set if record SQL |