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.

<!--start release-notes-assistant-->

## Draft release notes
<!--URL:https://codeberg.org/forgejo/forgejo-->
- Features
  - [PR](https://codeberg.org/forgejo/forgejo/pulls/2869): <!--number 2869 --><!--line 0 --><!--description bG9nOiBqb3VybmFsZCBpbnRlZ3JhdGlvbg==-->log: journald integration<!--description-->
<!--end release-notes-assistant-->

Reviewed-on: https://codeberg.org/forgejo/forgejo/pulls/2869
Reviewed-by: Earl Warren <earl-warren@noreply.codeberg.org>
Co-authored-by: Ivan Shapovalov <intelfx@intelfx.name>
Co-committed-by: Ivan Shapovalov <intelfx@intelfx.name>

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

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

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

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...)

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

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
+	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,
+	"journaldflags": LjournaldFlags,
 }
 
 var flagComboToString = []struct {

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 {

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
 }
 

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)