From 5422f23ed8174661b6e658250e4007b7fdf0d603 Mon Sep 17 00:00:00 2001 From: zeripath Date: Sun, 7 Apr 2019 01:25:14 +0100 Subject: [PATCH] Quieter Integration Tests (#6513) * Rename BaseLogger to WriterLogger to help the creation of other providers * Don't export ColorBytes and ResetBytes from ColoredValues * Make integration tests only print logs if they fail * check can color before coloring * I always forget about MSSQL * Oh and use LEVEL in sqlite.ini * Make the test logger log at info - as it means you see the router * Remove empty expected changes * Make the migrations quieter too * Don't display SQL on error - it can be looked at in the file logs if necessary * Fix skip when using onGiteaRun --- .../advanced/logging-documentation.en-us.md | 6 +- .../git_helper_for_declarative_test.go | 2 +- integrations/git_test.go | 25 ++ integrations/integration_test.go | 7 +- integrations/migration-test/migration_test.go | 28 +- integrations/mssql.ini.tmpl | 15 +- integrations/mysql.ini.tmpl | 15 +- integrations/mysql8.ini.tmpl | 16 +- integrations/pgsql.ini.tmpl | 15 +- integrations/sqlite.ini | 29 +- integrations/testlogger.go | 104 ++++++ modules/log/base.go | 328 ------------------ modules/log/colors.go | 40 ++- modules/log/conn.go | 4 +- modules/log/console.go | 8 +- modules/log/file.go | 4 +- modules/log/file_test.go | 2 - modules/log/flags.go | 64 ++++ modules/log/smtp.go | 4 +- modules/log/writer.go | 273 +++++++++++++++ modules/log/{base_test.go => writer_test.go} | 12 +- modules/setting/log.go | 9 + modules/setting/setting.go | 6 +- 23 files changed, 607 insertions(+), 409 deletions(-) create mode 100644 integrations/testlogger.go delete mode 100644 modules/log/base.go create mode 100644 modules/log/flags.go create mode 100644 modules/log/writer.go rename modules/log/{base_test.go => writer_test.go} (98%) diff --git a/docs/content/doc/advanced/logging-documentation.en-us.md b/docs/content/doc/advanced/logging-documentation.en-us.md index db8dcbba3..bef034e2e 100644 --- a/docs/content/doc/advanced/logging-documentation.en-us.md +++ b/docs/content/doc/advanced/logging-documentation.en-us.md @@ -357,10 +357,10 @@ attributes should be cached if this is a commonly used log message. of bytes representing the color. These functions will not double wrap a `log.ColoredValue`. They will -also set the ResetBytes to the cached resetBytes. +also set the `resetBytes` to the cached `resetBytes`. -Be careful not to change the contents of resetBytes or boldBytes as this -will break rendering of logging elsewhere. You have been warned. +The `colorBytes` and `resetBytes` are not exported to prevent +accidental overwriting of internal values. ## Log Spoofing protection diff --git a/integrations/git_helper_for_declarative_test.go b/integrations/git_helper_for_declarative_test.go index 010f47a7a..b4fead662 100644 --- a/integrations/git_helper_for_declarative_test.go +++ b/integrations/git_helper_for_declarative_test.go @@ -50,7 +50,7 @@ func createSSHUrl(gitPath string, u *url.URL) *url.URL { } func onGiteaRun(t *testing.T, callback func(*testing.T, *url.URL)) { - prepareTestEnv(t) + prepareTestEnv(t, 1) s := http.Server{ Handler: mac, } diff --git a/integrations/git_test.go b/integrations/git_test.go index 28ead9d38..ebbf04f9d 100644 --- a/integrations/git_test.go +++ b/integrations/git_test.go @@ -38,6 +38,7 @@ func testGit(t *testing.T, u *url.URL) { u.Path = baseAPITestContext.GitPath() t.Run("HTTP", func(t *testing.T) { + PrintCurrentTest(t) httpContext := baseAPITestContext httpContext.Reponame = "repo-tmp-17" @@ -47,6 +48,7 @@ func testGit(t *testing.T, u *url.URL) { assert.NoError(t, err) defer os.RemoveAll(dstPath) t.Run("Standard", func(t *testing.T) { + PrintCurrentTest(t) ensureAnonymousClone(t, u) t.Run("CreateRepo", doAPICreateRepository(httpContext, false)) @@ -57,16 +59,21 @@ func testGit(t *testing.T, u *url.URL) { t.Run("Clone", doGitClone(dstPath, u)) t.Run("PushCommit", func(t *testing.T) { + PrintCurrentTest(t) t.Run("Little", func(t *testing.T) { + PrintCurrentTest(t) little = commitAndPush(t, littleSize, dstPath) }) t.Run("Big", func(t *testing.T) { + PrintCurrentTest(t) big = commitAndPush(t, bigSize, dstPath) }) }) }) t.Run("LFS", func(t *testing.T) { + PrintCurrentTest(t) t.Run("PushCommit", func(t *testing.T) { + PrintCurrentTest(t) //Setup git LFS _, err = git.NewCommand("lfs").AddArguments("install").RunInDir(dstPath) assert.NoError(t, err) @@ -76,17 +83,21 @@ func testGit(t *testing.T, u *url.URL) { assert.NoError(t, err) t.Run("Little", func(t *testing.T) { + PrintCurrentTest(t) littleLFS = commitAndPush(t, littleSize, dstPath) }) t.Run("Big", func(t *testing.T) { + PrintCurrentTest(t) bigLFS = commitAndPush(t, bigSize, dstPath) }) }) t.Run("Locks", func(t *testing.T) { + PrintCurrentTest(t) lockTest(t, u.String(), dstPath) }) }) t.Run("Raw", func(t *testing.T) { + PrintCurrentTest(t) session := loginUser(t, "user2") // Request raw paths @@ -110,6 +121,7 @@ func testGit(t *testing.T, u *url.URL) { }) t.Run("Media", func(t *testing.T) { + PrintCurrentTest(t) session := loginUser(t, "user2") // Request media paths @@ -132,12 +144,14 @@ func testGit(t *testing.T, u *url.URL) { }) t.Run("SSH", func(t *testing.T) { + PrintCurrentTest(t) sshContext := baseAPITestContext sshContext.Reponame = "repo-tmp-18" keyname := "my-testing-key" //Setup key the user ssh key withKeyFile(t, keyname, func(keyFile string) { t.Run("CreateUserKey", doAPICreateUserKey(sshContext, "test-key", keyFile)) + PrintCurrentTest(t) //Setup remote link sshURL := createSSHUrl(sshContext.GitPath(), u) @@ -149,6 +163,7 @@ func testGit(t *testing.T, u *url.URL) { var little, big, littleLFS, bigLFS string t.Run("Standard", func(t *testing.T) { + PrintCurrentTest(t) t.Run("CreateRepo", doAPICreateRepository(sshContext, false)) //TODO get url from api @@ -156,16 +171,21 @@ func testGit(t *testing.T, u *url.URL) { //time.Sleep(5 * time.Minute) t.Run("PushCommit", func(t *testing.T) { + PrintCurrentTest(t) t.Run("Little", func(t *testing.T) { + PrintCurrentTest(t) little = commitAndPush(t, littleSize, dstPath) }) t.Run("Big", func(t *testing.T) { + PrintCurrentTest(t) big = commitAndPush(t, bigSize, dstPath) }) }) }) t.Run("LFS", func(t *testing.T) { + PrintCurrentTest(t) t.Run("PushCommit", func(t *testing.T) { + PrintCurrentTest(t) //Setup git LFS _, err = git.NewCommand("lfs").AddArguments("install").RunInDir(dstPath) assert.NoError(t, err) @@ -175,17 +195,21 @@ func testGit(t *testing.T, u *url.URL) { assert.NoError(t, err) t.Run("Little", func(t *testing.T) { + PrintCurrentTest(t) littleLFS = commitAndPush(t, littleSize, dstPath) }) t.Run("Big", func(t *testing.T) { + PrintCurrentTest(t) bigLFS = commitAndPush(t, bigSize, dstPath) }) }) t.Run("Locks", func(t *testing.T) { + PrintCurrentTest(t) lockTest(t, u.String(), dstPath) }) }) t.Run("Raw", func(t *testing.T) { + PrintCurrentTest(t) session := loginUser(t, "user2") // Request raw paths @@ -209,6 +233,7 @@ func testGit(t *testing.T, u *url.URL) { }) t.Run("Media", func(t *testing.T) { + PrintCurrentTest(t) session := loginUser(t, "user2") // Request media paths diff --git a/integrations/integration_test.go b/integrations/integration_test.go index d300e4a38..4263fa480 100644 --- a/integrations/integration_test.go +++ b/integrations/integration_test.go @@ -165,7 +165,12 @@ func initIntegrationTest() { routers.GlobalInit() } -func prepareTestEnv(t testing.TB) { +func prepareTestEnv(t testing.TB, skip ...int) { + ourSkip := 2 + if len(skip) > 0 { + ourSkip += skip[0] + } + PrintCurrentTest(t, ourSkip) assert.NoError(t, models.LoadFixtures()) assert.NoError(t, os.RemoveAll(setting.RepoRootPath)) assert.NoError(t, os.RemoveAll(models.LocalCopyPath())) diff --git a/integrations/migration-test/migration_test.go b/integrations/migration-test/migration_test.go index 6fd7af832..93b60e0e3 100644 --- a/integrations/migration-test/migration_test.go +++ b/integrations/migration-test/migration_test.go @@ -9,13 +9,13 @@ import ( "database/sql" "fmt" "io/ioutil" - "log" "os" "path" "regexp" "sort" "testing" + "code.gitea.io/gitea/integrations" "code.gitea.io/gitea/models" "code.gitea.io/gitea/models/migrations" "code.gitea.io/gitea/modules/setting" @@ -26,21 +26,22 @@ import ( var currentEngine *xorm.Engine -func initMigrationTest() { +func initMigrationTest(t *testing.T) { + integrations.PrintCurrentTest(t, 2) giteaRoot := os.Getenv("GITEA_ROOT") if giteaRoot == "" { - fmt.Println("Environment variable $GITEA_ROOT not set") + integrations.Printf("Environment variable $GITEA_ROOT not set\n") os.Exit(1) } setting.AppPath = path.Join(giteaRoot, "gitea") if _, err := os.Stat(setting.AppPath); err != nil { - fmt.Printf("Could not find gitea binary at %s\n", setting.AppPath) + integrations.Printf("Could not find gitea binary at %s\n", setting.AppPath) os.Exit(1) } giteaConf := os.Getenv("GITEA_CONF") if giteaConf == "" { - fmt.Println("Environment variable $GITEA_CONF not set") + integrations.Printf("Environment variable $GITEA_CONF not set\n") os.Exit(1) } else if !path.IsAbs(giteaConf) { setting.CustomConf = path.Join(giteaRoot, giteaConf) @@ -51,6 +52,7 @@ func initMigrationTest() { setting.NewContext() setting.CheckLFSVersion() models.LoadConfigs() + setting.NewLogServices(true) } func getDialect() string { @@ -125,7 +127,7 @@ func restoreOldDB(t *testing.T, version string) bool { data, err := readSQLFromFile(version) assert.NoError(t, err) if len(data) == 0 { - log.Printf("No db found to restore for %s version: %s\n", models.DbCfg.Type, version) + integrations.Printf("No db found to restore for %s version: %s\n", models.DbCfg.Type, version) return false } @@ -212,7 +214,8 @@ func wrappedMigrate(x *xorm.Engine) error { } func doMigrationTest(t *testing.T, version string) { - log.Printf("Performing migration test for %s version: %s", models.DbCfg.Type, version) + integrations.PrintCurrentTest(t) + integrations.Printf("Performing migration test for %s version: %s\n", models.DbCfg.Type, version) if !restoreOldDB(t, version) { return } @@ -227,19 +230,22 @@ func doMigrationTest(t *testing.T, version string) { } func TestMigrations(t *testing.T) { - initMigrationTest() + initMigrationTest(t) dialect := models.DbCfg.Type versions, err := availableVersions() assert.NoError(t, err) if len(versions) == 0 { - log.Printf("No old database versions available to migration test for %s\n", dialect) + integrations.Printf("No old database versions available to migration test for %s\n", dialect) return } - log.Printf("Preparing to test %d migrations for %s\n", len(versions), dialect) + integrations.Printf("Preparing to test %d migrations for %s\n", len(versions), dialect) for _, version := range versions { - doMigrationTest(t, version) + t.Run(fmt.Sprintf("Migrate-%s-%s", dialect, version), func(t *testing.T) { + doMigrationTest(t, version) + }) + } } diff --git a/integrations/mssql.ini.tmpl b/integrations/mssql.ini.tmpl index 86d100845..a8e6d332f 100644 --- a/integrations/mssql.ini.tmpl +++ b/integrations/mssql.ini.tmpl @@ -60,14 +60,19 @@ PROVIDER = file PROVIDER_CONFIG = data/sessions-mssql [log] -MODE = console,file -ROOT_PATH = mssql-log +MODE = test,file +ROOT_PATH = sqlite-log +REDIRECT_MACARON_LOG = true +ROUTER = , +MACARON = , +XORM = file -[log.console] -LEVEL = Warn +[log.test] +LEVEL = Info +COLORIZE = true [log.file] -LEVEL = Debug +LEVEL = Debug [security] INSTALL_LOCK = true diff --git a/integrations/mysql.ini.tmpl b/integrations/mysql.ini.tmpl index 0ba34f2d8..0c9e6c3ec 100644 --- a/integrations/mysql.ini.tmpl +++ b/integrations/mysql.ini.tmpl @@ -60,14 +60,19 @@ PROVIDER = file PROVIDER_CONFIG = data/sessions-mysql [log] -MODE = console,file -ROOT_PATH = mysql-log +MODE = test,file +ROOT_PATH = sqlite-log +REDIRECT_MACARON_LOG = true +ROUTER = , +MACARON = , +XORM = file -[log.console] -LEVEL = Warn +[log.test] +LEVEL = Info +COLORIZE = true [log.file] -LEVEL = Debug +LEVEL = Debug [security] INSTALL_LOCK = true diff --git a/integrations/mysql8.ini.tmpl b/integrations/mysql8.ini.tmpl index 246ec800a..700643327 100644 --- a/integrations/mysql8.ini.tmpl +++ b/integrations/mysql8.ini.tmpl @@ -57,14 +57,20 @@ PROVIDER = file PROVIDER_CONFIG = data/sessions-mysql8 [log] -MODE = console,file -ROOT_PATH = mysql8-log +MODE = test,file +ROOT_PATH = sqlite-log +REDIRECT_MACARON_LOG = true +ROUTER = , +MACARON = , +XORM = file -[log.console] -LEVEL = Warn +[log.test] +LEVEL = Info +COLORIZE = true [log.file] -LEVEL = Debug +LEVEL = Debug + [security] INSTALL_LOCK = true diff --git a/integrations/pgsql.ini.tmpl b/integrations/pgsql.ini.tmpl index e617b1899..894a243ba 100644 --- a/integrations/pgsql.ini.tmpl +++ b/integrations/pgsql.ini.tmpl @@ -60,14 +60,19 @@ PROVIDER = file PROVIDER_CONFIG = data/sessions-pgsql [log] -MODE = console,file -ROOT_PATH = pgsql-log +MODE = test,file +ROOT_PATH = sqlite-log +REDIRECT_MACARON_LOG = true +ROUTER = , +MACARON = , +XORM = file -[log.console] -LEVEL = Warn +[log.test] +LEVEL = Info +COLORIZE = true [log.file] -LEVEL = Debug +LEVEL = Debug [security] INSTALL_LOCK = true diff --git a/integrations/sqlite.ini b/integrations/sqlite.ini index f1e48617a..086081b66 100644 --- a/integrations/sqlite.ini +++ b/integrations/sqlite.ini @@ -33,18 +33,19 @@ APP_DATA_PATH = integrations/gitea-integration-sqlite/data ENABLE_GZIP = true [mailer] -ENABLED = false +ENABLED = true +MAILER_TYPE = dummy +FROM = sqlite-integration-test@gitea.io [service] REGISTER_EMAIL_CONFIRM = false -ENABLE_NOTIFY_MAIL = false +ENABLE_NOTIFY_MAIL = true DISABLE_REGISTRATION = false ENABLE_CAPTCHA = false REQUIRE_SIGNIN_VIEW = false DEFAULT_KEEP_EMAIL_PRIVATE = false DEFAULT_ALLOW_CREATE_ORGANIZATION = true NO_REPLY_ADDRESS = noreply.example.org -ENABLE_NOTIFY_MAIL = true [picture] DISABLE_GRAVATAR = false @@ -54,21 +55,25 @@ ENABLE_FEDERATED_AVATAR = false PROVIDER = file [log] -MODE = console,file -ROOT_PATH = sqlite-log +MODE = test,file +ROOT_PATH = sqlite-log +REDIRECT_MACARON_LOG = true +ROUTER = , +MACARON = , +XORM = file -[log.console] -LEVEL = Warn +[log.test] +LEVEL = Info +COLORIZE = true [log.file] -LEVEL = Debug +LEVEL = Debug [security] INSTALL_LOCK = true SECRET_KEY = 9pCviYTWSb INTERNAL_TOKEN = eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJuYmYiOjE0OTI3OTU5ODN9.OQkH5UmzID2XBdwQ9TAI6Jj2t1X-wElVTjbE7aoN4I8 -[mailer] -ENABLED = true -MAILER_TYPE = dummy -FROM = sqlite-integration-test@gitea.io +[oauth2] +JWT_SECRET = KZb_QLUd4fYVyxetjxC4eZkrBgWM2SndOOWDNtgUUko + diff --git a/integrations/testlogger.go b/integrations/testlogger.go new file mode 100644 index 000000000..9ee28d2ea --- /dev/null +++ b/integrations/testlogger.go @@ -0,0 +1,104 @@ +// 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 integrations + +import ( + "encoding/json" + "fmt" + "os" + "runtime" + "strings" + "testing" + + "code.gitea.io/gitea/modules/log" +) + +var prefix string + +// TestLogger is a logger which will write to the testing log +type TestLogger struct { + log.WriterLogger +} + +var writerCloser = &testLoggerWriterCloser{} + +type testLoggerWriterCloser struct { + t testing.TB +} + +func (w *testLoggerWriterCloser) Write(p []byte) (int, error) { + if w.t != nil { + if len(p) > 0 && p[len(p)-1] == '\n' { + p = p[:len(p)-1] + } + w.t.Log(string(p)) + return len(p), nil + } + return len(p), nil +} + +func (w *testLoggerWriterCloser) Close() error { + return nil +} + +// PrintCurrentTest prints the current test to os.Stdout +func PrintCurrentTest(t testing.TB, skip ...int) { + actualSkip := 1 + if len(skip) > 0 { + actualSkip = skip[0] + } + _, filename, line, _ := runtime.Caller(actualSkip) + + if log.CanColorStdout { + fmt.Fprintf(os.Stdout, "=== %s (%s:%d)\n", log.NewColoredValue(t.Name()), strings.TrimPrefix(filename, prefix), line) + } else { + fmt.Fprintf(os.Stdout, "=== %s (%s:%d)\n", t.Name(), strings.TrimPrefix(filename, prefix), line) + } + writerCloser.t = t +} + +// Printf takes a format and args and prints the string to os.Stdout +func Printf(format string, args ...interface{}) { + if log.CanColorStdout { + for i := 0; i < len(args); i++ { + args[i] = log.NewColoredValue(args[i]) + } + } + fmt.Fprintf(os.Stdout, "\t"+format, args...) +} + +// NewTestLogger creates a TestLogger as a log.LoggerProvider +func NewTestLogger() log.LoggerProvider { + logger := &TestLogger{} + logger.Colorize = log.CanColorStdout + logger.Level = log.TRACE + return logger +} + +// Init inits connection writer with json config. +// json config only need key "level". +func (log *TestLogger) Init(config string) error { + err := json.Unmarshal([]byte(config), log) + if err != nil { + return err + } + log.NewWriterLogger(writerCloser) + return nil +} + +// Flush when log should be flushed +func (log *TestLogger) Flush() { +} + +// GetName returns the default name for this implementation +func (log *TestLogger) GetName() string { + return "test" +} + +func init() { + log.Register("test", NewTestLogger) + _, filename, _, _ := runtime.Caller(0) + prefix = strings.TrimSuffix(filename, "integrations/testlogger.go") +} diff --git a/modules/log/base.go b/modules/log/base.go deleted file mode 100644 index 5577737e0..000000000 --- a/modules/log/base.go +++ /dev/null @@ -1,328 +0,0 @@ -// 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/colors.go b/modules/log/colors.go index fa8a664f0..ed6477d43 100644 --- a/modules/log/colors.go +++ b/modules/log/colors.go @@ -268,8 +268,8 @@ normalLoop: // ColoredValue will Color the provided value type ColoredValue struct { - ColorBytes *[]byte - ResetBytes *[]byte + colorBytes *[]byte + resetBytes *[]byte Value *interface{} } @@ -290,14 +290,14 @@ func NewColoredValuePointer(value *interface{}, color ...ColorAttribute) *Colore if len(color) > 0 { bytes := ColorBytes(color...) return &ColoredValue{ - ColorBytes: &bytes, - ResetBytes: &resetBytes, + colorBytes: &bytes, + resetBytes: &resetBytes, Value: value, } } return &ColoredValue{ - ColorBytes: &fgBoldBytes, - ResetBytes: &resetBytes, + colorBytes: &fgBoldBytes, + resetBytes: &resetBytes, Value: value, } @@ -310,17 +310,37 @@ func NewColoredValueBytes(value interface{}, colorBytes *[]byte) *ColoredValue { return val } return &ColoredValue{ - ColorBytes: colorBytes, - ResetBytes: &resetBytes, + 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)) + s.Write([]byte(*cv.colorBytes)) fmt.Fprintf(&protectedANSIWriter{w: s}, fmtString(s, c), *(cv.Value)) - s.Write([]byte(*cv.ResetBytes)) + s.Write([]byte(*cv.resetBytes)) +} + +// SetColorBytes will allow a user to set the colorBytes of a colored value +func (cv *ColoredValue) SetColorBytes(colorBytes []byte) { + cv.colorBytes = &colorBytes +} + +// SetColorBytesPointer will allow a user to set the colorBytes pointer of a colored value +func (cv *ColoredValue) SetColorBytesPointer(colorBytes *[]byte) { + cv.colorBytes = colorBytes +} + +// SetResetBytes will allow a user to set the resetBytes pointer of a colored value +func (cv *ColoredValue) SetResetBytes(resetBytes []byte) { + cv.resetBytes = &resetBytes +} + +// SetResetBytesPointer will allow a user to set the resetBytes pointer of a colored value +func (cv *ColoredValue) SetResetBytesPointer(resetBytes *[]byte) { + cv.resetBytes = resetBytes } func fmtString(s fmt.State, c rune) string { diff --git a/modules/log/conn.go b/modules/log/conn.go index d48bb4b33..bd7685516 100644 --- a/modules/log/conn.go +++ b/modules/log/conn.go @@ -77,7 +77,7 @@ func (i *connWriter) connect() error { // ConnLogger implements LoggerProvider. // it writes messages in keep-live tcp connection. type ConnLogger struct { - BaseLogger + WriterLogger ReconnectOnMsg bool `json:"reconnectOnMsg"` Reconnect bool `json:"reconnect"` Net string `json:"net"` @@ -98,7 +98,7 @@ func (log *ConnLogger) Init(jsonconfig string) error { if err != nil { return err } - log.createLogger(&connWriter{ + log.NewWriterLogger(&connWriter{ ReconnectOnMsg: log.ReconnectOnMsg, Reconnect: log.Reconnect, Net: log.Net, diff --git a/modules/log/console.go b/modules/log/console.go index cf2dfa499..6cfca8a73 100644 --- a/modules/log/console.go +++ b/modules/log/console.go @@ -34,14 +34,14 @@ func (n *nopWriteCloser) Close() error { // ConsoleLogger implements LoggerProvider and writes messages to terminal. type ConsoleLogger struct { - BaseLogger + WriterLogger Stderr bool `json:"stderr"` } // NewConsoleLogger create ConsoleLogger returning as LoggerProvider. func NewConsoleLogger() LoggerProvider { log := &ConsoleLogger{} - log.createLogger(&nopWriteCloser{ + log.NewWriterLogger(&nopWriteCloser{ w: os.Stdout, }) return log @@ -55,11 +55,11 @@ func (log *ConsoleLogger) Init(config string) error { return err } if log.Stderr { - log.createLogger(&nopWriteCloser{ + log.NewWriterLogger(&nopWriteCloser{ w: os.Stderr, }) } else { - log.createLogger(log.out) + log.NewWriterLogger(log.out) } return nil } diff --git a/modules/log/file.go b/modules/log/file.go index 5c219c391..cdda85d62 100644 --- a/modules/log/file.go +++ b/modules/log/file.go @@ -20,7 +20,7 @@ import ( // FileLogger implements LoggerProvider. // It writes messages by lines limit, file size limit, or time frequency. type FileLogger struct { - BaseLogger + WriterLogger mw *MuxWriter // The opened file Filename string `json:"filename"` @@ -106,7 +106,7 @@ func (log *FileLogger) Init(config string) error { return errors.New("config must have filename") } // set MuxWriter as Logger's io.Writer - log.createLogger(log.mw) + log.NewWriterLogger(log.mw) return log.StartLogger() } diff --git a/modules/log/file_test.go b/modules/log/file_test.go index 952706907..648db6f39 100644 --- a/modules/log/file_test.go +++ b/modules/log/file_test.go @@ -89,7 +89,6 @@ func TestFileLogger(t *testing.T) { assert.Equal(t, expected, string(logData)) event.level = DEBUG - expected = expected + "" fileLogger.LogEvent(&event) fileLogger.Flush() logData, err = ioutil.ReadFile(filename) @@ -97,7 +96,6 @@ func TestFileLogger(t *testing.T) { assert.Equal(t, expected, string(logData)) event.level = TRACE - expected = expected + "" fileLogger.LogEvent(&event) fileLogger.Flush() logData, err = ioutil.ReadFile(filename) diff --git a/modules/log/flags.go b/modules/log/flags.go new file mode 100644 index 000000000..928d42b96 --- /dev/null +++ b/modules/log/flags.go @@ -0,0 +1,64 @@ +// 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 "strings" + +// 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/logger/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/logger/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 +} diff --git a/modules/log/smtp.go b/modules/log/smtp.go index 2e78d713c..f77d716d9 100644 --- a/modules/log/smtp.go +++ b/modules/log/smtp.go @@ -31,7 +31,7 @@ func (s *smtpWriter) Close() error { // SMTPLogger implements LoggerProvider and is used to send emails via given SMTP-server. type SMTPLogger struct { - BaseLogger + WriterLogger Username string `json:"Username"` Password string `json:"password"` Host string `json:"host"` @@ -63,7 +63,7 @@ func (log *SMTPLogger) Init(jsonconfig string) error { if err != nil { return err } - log.createLogger(&smtpWriter{ + log.NewWriterLogger(&smtpWriter{ owner: log, }) log.sendMailFn = smtp.SendMail diff --git a/modules/log/writer.go b/modules/log/writer.go new file mode 100644 index 000000000..22ef0b904 --- /dev/null +++ b/modules/log/writer.go @@ -0,0 +1,273 @@ +// 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" +) + +type byteArrayWriter []byte + +func (b *byteArrayWriter) Write(p []byte) (int, error) { + *b = append(*b, p...) + return len(p), nil +} + +// WriterLogger represent a basic logger for Gitea +type WriterLogger 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 +} + +// NewWriterLogger creates a new WriterLogger from the provided WriteCloser. +// Optionally the level can be changed at the same time. +func (logger *WriterLogger) NewWriterLogger(out io.WriteCloser, level ...Level) { + logger.mu.Lock() + defer logger.mu.Unlock() + logger.out = out + switch logger.Flags { + case 0: + logger.Flags = LstdFlags + case -1: + logger.Flags = 0 + } + if len(level) > 0 { + logger.Level = level[0] + } + logger.createExpression() +} + +func (logger *WriterLogger) createExpression() { + if len(logger.Expression) > 0 { + var err error + logger.regexp, err = regexp.Compile(logger.Expression) + if err != nil { + logger.regexp = nil + } + } +} + +// GetLevel returns the logging level for this logger +func (logger *WriterLogger) GetLevel() Level { + return logger.Level +} + +// GetStacktraceLevel returns the stacktrace logging level for this logger +func (logger *WriterLogger) GetStacktraceLevel() Level { + return logger.StacktraceLevel +} + +// Copy of cheap integer to fixed-width decimal to ascii from logger. +func itoa(buf *[]byte, i int, wid int) { + var logger [20]byte + bp := len(logger) - 1 + for i >= 10 || wid > 1 { + wid-- + q := i / 10 + logger[bp] = byte('0' + i - q*10) + bp-- + i = q + } + // i < 10 + logger[bp] = byte('0' + i) + *buf = append(*buf, logger[bp:]...) +} + +func (logger *WriterLogger) createMsg(buf *[]byte, event *Event) { + *buf = append(*buf, logger.Prefix...) + t := event.time + if logger.Flags&(Ldate|Ltime|Lmicroseconds) != 0 { + if logger.Colorize { + *buf = append(*buf, fgCyanBytes...) + } + if logger.Flags&LUTC != 0 { + t = t.UTC() + } + if logger.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 logger.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 logger.Flags&Lmicroseconds != 0 { + *buf = append(*buf, '.') + itoa(buf, t.Nanosecond()/1e3, 6) + } + *buf = append(*buf, ' ') + } + if logger.Colorize { + *buf = append(*buf, resetBytes...) + } + + } + if logger.Flags&(Lshortfile|Llongfile) != 0 { + if logger.Colorize { + *buf = append(*buf, fgGreenBytes...) + } + file := event.filename + if logger.Flags&Lmedfile == Lmedfile { + startIndex := len(file) - 20 + if startIndex > 0 { + file = "..." + file[startIndex:] + } + } else if logger.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 logger.Flags&(Lfuncname|Lshortfuncname) != 0 { + *buf = append(*buf, ':') + } else { + if logger.Colorize { + *buf = append(*buf, resetBytes...) + } + *buf = append(*buf, ' ') + } + } + if logger.Flags&(Lfuncname|Lshortfuncname) != 0 { + if logger.Colorize { + *buf = append(*buf, fgGreenBytes...) + } + funcname := event.caller + if logger.Flags&Lshortfuncname != 0 { + lastIndex := strings.LastIndexByte(funcname, '.') + if lastIndex > 0 && len(funcname) > lastIndex+1 { + funcname = funcname[lastIndex+1:] + } + } + *buf = append(*buf, funcname...) + if logger.Colorize { + *buf = append(*buf, resetBytes...) + } + *buf = append(*buf, ' ') + + } + if logger.Flags&(Llevel|Llevelinitial) != 0 { + level := strings.ToUpper(event.level.String()) + if logger.Colorize { + *buf = append(*buf, levelToColor[event.level]...) + } + *buf = append(*buf, '[') + if logger.Flags&Llevelinitial != 0 { + *buf = append(*buf, level[0]) + } else { + *buf = append(*buf, level...) + } + *buf = append(*buf, ']') + if logger.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 !logger.Colorize { + pawMode = removeColor + } + + baw := byteArrayWriter(*buf) + (&protectedANSIWriter{ + w: &baw, + mode: pawMode, + }).Write([]byte(msg)) + *buf = baw + + if event.stacktrace != "" && logger.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 (logger *WriterLogger) LogEvent(event *Event) error { + if logger.Level > event.level { + return nil + } + + logger.mu.Lock() + defer logger.mu.Unlock() + if !logger.Match(event) { + return nil + } + var buf []byte + logger.createMsg(&buf, event) + _, err := logger.out.Write(buf) + return err +} + +// Match checks if the given event matches the logger's regexp expression +func (logger *WriterLogger) Match(event *Event) bool { + if logger.regexp == nil { + return true + } + if logger.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 logger.regexp.Match(msg) { + return true + } + return false +} + +// Close the base logger +func (logger *WriterLogger) Close() { + logger.mu.Lock() + defer logger.mu.Unlock() + if logger.out != nil { + logger.out.Close() + } +} + +// GetName returns empty for these provider loggers +func (logger *WriterLogger) GetName() string { + return "" +} diff --git a/modules/log/base_test.go b/modules/log/writer_test.go similarity index 98% rename from modules/log/base_test.go rename to modules/log/writer_test.go index 3686c26ce..886dd58fb 100644 --- a/modules/log/base_test.go +++ b/modules/log/writer_test.go @@ -38,7 +38,7 @@ func TestBaseLogger(t *testing.T) { }, } prefix := "TestPrefix " - b := BaseLogger{ + b := WriterLogger{ out: c, Level: INFO, Flags: LstdFlags | LUTC, @@ -115,7 +115,7 @@ func TestBaseLoggerDated(t *testing.T) { }, } prefix := "" - b := BaseLogger{ + b := WriterLogger{ out: c, Level: WARN, Flags: Ldate | Ltime | Lmicroseconds | Lshortfile | Llevel, @@ -195,14 +195,14 @@ func TestBaseLoggerMultiLineNoFlagsRegexp(t *testing.T) { }, } prefix := "" - b := BaseLogger{ + b := WriterLogger{ Level: DEBUG, StacktraceLevel: ERROR, Flags: -1, Prefix: prefix, Expression: "FILENAME", } - b.createLogger(c) + b.NewWriterLogger(c) location, _ := time.LoadLocation("EST") @@ -263,14 +263,14 @@ func TestBrokenRegexp(t *testing.T) { }, } - b := BaseLogger{ + b := WriterLogger{ Level: DEBUG, StacktraceLevel: ERROR, Flags: -1, Prefix: prefix, Expression: "\\", } - b.createLogger(c) + b.NewWriterLogger(c) assert.Empty(t, b.regexp) b.Close() assert.Equal(t, true, closed) diff --git a/modules/setting/log.go b/modules/setting/log.go index c6b5b1a61..aafb4b372 100644 --- a/modules/setting/log.go +++ b/modules/setting/log.go @@ -273,6 +273,15 @@ func newLogService() { golog.SetOutput(log.NewLoggerAsWriter("INFO", log.GetLogger(log.DEFAULT))) } +// NewLogServices creates all the log services +func NewLogServices(disableConsole bool) { + newLogService() + newMacaronLogService() + newRouterLogService() + newAccessLogService() + NewXORMLogService(disableConsole) +} + // NewXORMLogService initializes xorm logger service func NewXORMLogService(disableConsole bool) { EnableXORMLog = Cfg.Section("log").Key("ENABLE_XORM_LOG").MustBool(true) diff --git a/modules/setting/setting.go b/modules/setting/setting.go index b6c574002..ab290fc4f 100644 --- a/modules/setting/setting.go +++ b/modules/setting/setting.go @@ -982,11 +982,7 @@ func loadOrGenerateInternalToken(sec *ini.Section) string { // NewServices initializes the services func NewServices() { newService() - newLogService() - newMacaronLogService() - newAccessLogService() - newRouterLogService() - NewXORMLogService(false) + NewLogServices(false) newCacheService() newSessionService() newMailService()