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

1 files changed, 277 insertions, 0 deletions

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)
+}