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, 240 insertions, 0 deletions

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