From 012a1e0497bce557658a3f00485bf67d01cb9252 Mon Sep 17 00:00:00 2001 From: Ivan Shapovalov Date: Fri, 9 Aug 2024 07:49:13 +0000 Subject: [PATCH] log: journald integration (#2869) Provide a bit more journald integration. Specifically: - support emission of printk-style log level prefixes, documented in [`sd-daemon`(3)](https://man7.org/linux/man-pages/man3/sd-daemon.3.html#DESCRIPTION), that allow journald to automatically annotate stderr log lines with their level; - add a new "journaldflags" item that is supposed to be used in place of "stdflags" when under journald to reduce log clutter (i. e. strip date/time info to avoid duplication, and use log level prefixes instead of textual log levels); - detect whether stderr and/or stdout are attached to journald by parsing `$JOURNAL_STREAM` environment variable and adjust console logger defaults accordingly. ## Draft release notes - Features - [PR](https://codeberg.org/forgejo/forgejo/pulls/2869): log: journald integration Reviewed-on: https://codeberg.org/forgejo/forgejo/pulls/2869 Reviewed-by: Earl Warren Co-authored-by: Ivan Shapovalov Co-committed-by: Ivan Shapovalov --- custom/conf/app.example.ini | 2 +- modules/log/color_console.go | 13 ++++--- modules/log/color_console_other.go | 53 ++++++++++++++++++++++++-- modules/log/event_format.go | 10 ++++- modules/log/event_format_test.go | 61 +++++++++++++++++++++++++++++- modules/log/flags.go | 12 ++++-- modules/log/level.go | 20 ++++++++++ modules/setting/log.go | 14 ++++++- modules/setting/setting.go | 2 + 9 files changed, 169 insertions(+), 18 deletions(-) diff --git a/custom/conf/app.example.ini b/custom/conf/app.example.ini index a22276a0d6..804440dfc9 100644 --- a/custom/conf/app.example.ini +++ b/custom/conf/app.example.ini @@ -635,7 +635,7 @@ LEVEL = Info ;[log.%(WriterMode)] ;MODE=console/file/conn/... ;LEVEL= -;FLAGS = stdflags +;FLAGS = stdflags or journald ;EXPRESSION = ;PREFIX = ;COLORIZE = false diff --git a/modules/log/color_console.go b/modules/log/color_console.go index 2658652ec6..82b5ce18f8 100644 --- a/modules/log/color_console.go +++ b/modules/log/color_console.go @@ -4,11 +4,14 @@ package log -// 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 +// CanColorStdout reports if we can use ANSI escape sequences on stdout var CanColorStdout = true -// CanColorStderr reports if we can color the Stderr +// CanColorStderr reports if we can use ANSI escape sequences on stderr var CanColorStderr = true + +// JournaldOnStdout reports whether stdout is attached to journald +var JournaldOnStdout = false + +// JournaldOnStderr reports whether stderr is attached to journald +var JournaldOnStderr = false diff --git a/modules/log/color_console_other.go b/modules/log/color_console_other.go index c30be41544..673377fa62 100644 --- a/modules/log/color_console_other.go +++ b/modules/log/color_console_other.go @@ -7,14 +7,61 @@ package log import ( "os" + "strconv" + "strings" + "syscall" "github.com/mattn/go-isatty" ) +func journaldDevIno() (uint64, uint64, bool) { + journaldStream := os.Getenv("JOURNAL_STREAM") + if len(journaldStream) == 0 { + return 0, 0, false + } + deviceStr, inodeStr, ok := strings.Cut(journaldStream, ":") + device, err1 := strconv.ParseUint(deviceStr, 10, 64) + inode, err2 := strconv.ParseUint(inodeStr, 10, 64) + if !ok || err1 != nil || err2 != nil { + return 0, 0, false + } + return device, inode, true +} + +func fileStatDevIno(file *os.File) (uint64, uint64, bool) { + info, err := file.Stat() + if err != nil { + return 0, 0, false + } + + stat, ok := info.Sys().(*syscall.Stat_t) + if !ok { + return 0, 0, false + } + + return stat.Dev, stat.Ino, true +} + +func fileIsDevIno(file *os.File, dev, ino uint64) bool { + fileDev, fileIno, ok := fileStatDevIno(file) + return ok && dev == fileDev && ino == fileIno +} + func init() { - // when running gitea as a systemd unit with logging set to console, the output can not be colorized, - // otherwise it spams the journal / syslog with escape sequences like "#033[0m#033[32mcmd/web.go:102:#033[32m" - // this file covers non-windows platforms. + // When forgejo is running under service supervisor (e.g. systemd) with logging + // set to console, the output streams are typically captured into some logging + // system (e.g. journald or syslog) instead of going to the terminal. Disable + // usage of ANSI escape sequences if that's the case to avoid spamming + // the journal or syslog with garbled mess e.g. `#033[0m#033[32mcmd/web.go:102:#033[32m`. CanColorStdout = isatty.IsTerminal(os.Stdout.Fd()) CanColorStderr = isatty.IsTerminal(os.Stderr.Fd()) + + // Furthermore, check if we are running under journald specifically so that + // further output adjustments can be applied. Specifically, this changes + // the console logger defaults to disable duplication of date/time info and + // enable emission of special control sequences understood by journald + // instead of ANSI colors. + journalDev, journalIno, ok := journaldDevIno() + JournaldOnStdout = ok && !CanColorStdout && fileIsDevIno(os.Stdout, journalDev, journalIno) + JournaldOnStderr = ok && !CanColorStderr && fileIsDevIno(os.Stderr, journalDev, journalIno) } diff --git a/modules/log/event_format.go b/modules/log/event_format.go index 583ddf66dd..df6b083a92 100644 --- a/modules/log/event_format.go +++ b/modules/log/event_format.go @@ -90,9 +90,17 @@ func colorSprintf(colorize bool, format string, args ...any) string { // EventFormatTextMessage makes the log message for a writer with its mode. This function is a copy of the original package func EventFormatTextMessage(mode *WriterMode, event *Event, msgFormat string, msgArgs ...any) []byte { buf := make([]byte, 0, 1024) - buf = append(buf, mode.Prefix...) t := event.Time flags := mode.Flags.Bits() + + // if log level prefixes are enabled, the message must begin with the prefix, see sd_daemon(3) + // "A line that is not prefixed will be logged at the default log level SD_INFO" + if flags&Llevelprefix != 0 { + prefix := event.Level.JournalPrefix() + buf = append(buf, prefix...) + } + + buf = append(buf, mode.Prefix...) if flags&(Ldate|Ltime|Lmicroseconds) != 0 { if mode.Colorize { buf = append(buf, fgCyanBytes...) diff --git a/modules/log/event_format_test.go b/modules/log/event_format_test.go index 7c299a607d..0c6061eaea 100644 --- a/modules/log/event_format_test.go +++ b/modules/log/event_format_test.go @@ -35,7 +35,7 @@ func TestEventFormatTextMessage(t *testing.T) { "msg format: %v %v", "arg0", NewColoredValue("arg1", FgBlue), ) - assert.Equal(t, `[PREFIX] 2020/01/02 03:04:05.000000 filename:123:caller [E] [pid] msg format: arg0 arg1 + assert.Equal(t, `<3>[PREFIX] 2020/01/02 03:04:05.000000 filename:123:caller [E] [pid] msg format: arg0 arg1 stacktrace `, string(res)) @@ -53,5 +53,62 @@ func TestEventFormatTextMessage(t *testing.T) { "msg format: %v %v", "arg0", NewColoredValue("arg1", FgBlue), ) - assert.Equal(t, "[PREFIX] \x1b[36m2020/01/02 03:04:05.000000 \x1b[0m\x1b[32mfilename:123:\x1b[32mcaller\x1b[0m \x1b[1;31m[E]\x1b[0m [\x1b[93mpid\x1b[0m] msg format: arg0 \x1b[34marg1\x1b[0m\n\tstacktrace\n\n", string(res)) + assert.Equal(t, "<3>[PREFIX] \x1b[36m2020/01/02 03:04:05.000000 \x1b[0m\x1b[32mfilename:123:\x1b[32mcaller\x1b[0m \x1b[1;31m[E]\x1b[0m [\x1b[93mpid\x1b[0m] msg format: arg0 \x1b[34marg1\x1b[0m\n\tstacktrace\n\n", string(res)) +} + +func TestEventFormatTextMessageStd(t *testing.T) { + res := EventFormatTextMessage(&WriterMode{Prefix: "[PREFIX] ", Colorize: false, Flags: Flags{defined: true, flags: LstdFlags}}, + &Event{ + Time: time.Date(2020, 1, 2, 3, 4, 5, 6, time.UTC), + Caller: "caller", + Filename: "filename", + Line: 123, + GoroutinePid: "pid", + Level: ERROR, + Stacktrace: "stacktrace", + }, + "msg format: %v %v", "arg0", NewColoredValue("arg1", FgBlue), + ) + + assert.Equal(t, `[PREFIX] 2020/01/02 03:04:05 filename:123:caller [E] msg format: arg0 arg1 + stacktrace + +`, string(res)) + + res = EventFormatTextMessage(&WriterMode{Prefix: "[PREFIX] ", Colorize: true, Flags: Flags{defined: true, flags: LstdFlags}}, + &Event{ + Time: time.Date(2020, 1, 2, 3, 4, 5, 6, time.UTC), + Caller: "caller", + Filename: "filename", + Line: 123, + GoroutinePid: "pid", + Level: ERROR, + Stacktrace: "stacktrace", + }, + "msg format: %v %v", "arg0", NewColoredValue("arg1", FgBlue), + ) + + assert.Equal(t, "[PREFIX] \x1b[36m2020/01/02 03:04:05 \x1b[0m\x1b[32mfilename:123:\x1b[32mcaller\x1b[0m \x1b[1;31m[E]\x1b[0m msg format: arg0 \x1b[34marg1\x1b[0m\n\tstacktrace\n\n", string(res)) +} + +func TestEventFormatTextMessageJournal(t *testing.T) { + // TODO: it makes no sense to emit \n-containing messages to journal as they will get mangled + // the proper way here is to attach the backtrace as structured metadata, but we can't do that via stderr + res := EventFormatTextMessage(&WriterMode{Prefix: "[PREFIX] ", Colorize: false, Flags: Flags{defined: true, flags: LjournaldFlags}}, + &Event{ + Time: time.Date(2020, 1, 2, 3, 4, 5, 6, time.UTC), + Caller: "caller", + Filename: "filename", + Line: 123, + GoroutinePid: "pid", + Level: ERROR, + Stacktrace: "stacktrace", + }, + "msg format: %v %v", "arg0", NewColoredValue("arg1", FgBlue), + ) + + assert.Equal(t, `<3>[PREFIX] msg format: arg0 arg1 + stacktrace + +`, string(res)) } diff --git a/modules/log/flags.go b/modules/log/flags.go index f025159d53..cadf54fdd3 100644 --- a/modules/log/flags.go +++ b/modules/log/flags.go @@ -31,9 +31,11 @@ const ( Llevelinitial // Initial character of the provided level in brackets, eg. [I] for info Llevel // Provided level in brackets [INFO] Lgopid // the Goroutine-PID of the context + Llevelprefix // printk-style logging prefixes as documented in sd-daemon(3), used by journald - Lmedfile = Lshortfile | Llongfile // last 20 characters of the filename - LstdFlags = Ldate | Ltime | Lmedfile | Lshortfuncname | Llevelinitial // default + Lmedfile = Lshortfile | Llongfile // last 20 characters of the filename + LstdFlags = Ldate | Ltime | Lmedfile | Lshortfuncname | Llevelinitial // default + LjournaldFlags = Llevelprefix ) const Ldefault = LstdFlags @@ -54,10 +56,12 @@ var flagFromString = map[string]uint32{ "utc": LUTC, "levelinitial": Llevelinitial, "level": Llevel, + "levelprefix": Llevelprefix, "gopid": Lgopid, - "medfile": Lmedfile, - "stdflags": LstdFlags, + "medfile": Lmedfile, + "stdflags": LstdFlags, + "journaldflags": LjournaldFlags, } var flagComboToString = []struct { diff --git a/modules/log/level.go b/modules/log/level.go index 01fa3f5e46..47f7b83f0b 100644 --- a/modules/log/level.go +++ b/modules/log/level.go @@ -39,6 +39,22 @@ var toString = map[Level]string{ NONE: "none", } +// Machine-readable log level prefixes as defined in sd-daemon(3). +// +// "If a systemd service definition file is configured with StandardError=journal +// or StandardError=kmsg (and similar with StandardOutput=), these prefixes can +// be used to encode a log level in lines printed. <...> To use these prefixes +// simply prefix every line with one of these strings. A line that is not prefixed +// will be logged at the default log level SD_INFO." +var toJournalPrefix = map[Level]string{ + TRACE: "<7>", // SD_DEBUG + DEBUG: "<6>", // SD_INFO + INFO: "<5>", // SD_NOTICE + WARN: "<4>", // SD_WARNING + ERROR: "<3>", // SD_ERR + FATAL: "<2>", // SD_CRIT +} + var toLevel = map[string]Level{ "undefined": UNDEFINED, @@ -71,6 +87,10 @@ func (l Level) String() string { return "info" } +func (l Level) JournalPrefix() string { + return toJournalPrefix[l] +} + func (l Level) ColorAttributes() []ColorAttribute { color, ok := levelToColor[l] if ok { diff --git a/modules/setting/log.go b/modules/setting/log.go index e404074b72..a141188c0c 100644 --- a/modules/setting/log.go +++ b/modules/setting/log.go @@ -133,18 +133,25 @@ func loadLogModeByName(rootCfg ConfigProvider, loggerName, modeName string) (wri writerMode.StacktraceLevel = log.LevelFromString(ConfigInheritedKeyString(sec, "STACKTRACE_LEVEL", Log.StacktraceLogLevel.String())) writerMode.Prefix = ConfigInheritedKeyString(sec, "PREFIX") writerMode.Expression = ConfigInheritedKeyString(sec, "EXPRESSION") - writerMode.Flags = log.FlagsFromString(ConfigInheritedKeyString(sec, "FLAGS", defaultFlags)) + // flags are updated and set below switch writerType { case "console": - useStderr := ConfigInheritedKey(sec, "STDERR").MustBool(false) + // if stderr is on journald, prefer stderr by default + useStderr := ConfigInheritedKey(sec, "STDERR").MustBool(log.JournaldOnStderr) defaultCanColor := log.CanColorStdout + defaultJournald := log.JournaldOnStdout if useStderr { defaultCanColor = log.CanColorStderr + defaultJournald = log.JournaldOnStderr } writerOption := log.WriterConsoleOption{Stderr: useStderr} writerMode.Colorize = ConfigInheritedKey(sec, "COLORIZE").MustBool(defaultCanColor) writerMode.WriterOption = writerOption + // if we are ultimately on journald, update default flags + if defaultJournald { + defaultFlags = "journaldflags" + } case "file": fileName := LogPrepareFilenameForWriter(ConfigInheritedKey(sec, "FILE_NAME").String(), defaultFilaName) writerOption := log.WriterFileOption{} @@ -169,6 +176,9 @@ func loadLogModeByName(rootCfg ConfigProvider, loggerName, modeName string) (wri } } + // set flags last because the console writer code may update default flags + writerMode.Flags = log.FlagsFromString(ConfigInheritedKeyString(sec, "FLAGS", defaultFlags)) + return writerName, writerType, writerMode, nil } diff --git a/modules/setting/setting.go b/modules/setting/setting.go index 892e41cddf..c9d30836ac 100644 --- a/modules/setting/setting.go +++ b/modules/setting/setting.go @@ -230,6 +230,8 @@ func LoadSettings() { // LoadSettingsForInstall initializes the settings for install func LoadSettingsForInstall() { + initAllLoggers() + loadDBSetting(CfgProvider) loadServiceFrom(CfgProvider) loadMailerFrom(CfgProvider)