[feature] Make log format configurable (#2130)

* [feature] Don't emit timestamp in log lines

When running gotosocial with a service manager like systemd, or a
container runtime, the associated log driver usually emits timestamps
itself. In those cases, having the extra timestamp from our own log
lines ends up being a bit noisy and when centrally ingesting logs is
duplicate information.

This introduces a configuration flag that allows disabling emitting the
timestamp. It's only wired up for "daemonised" processes, meaning server
and testrig.

* [chore] Add docs for log-timestamp

* [feature] Simplify timestamp handling

Co-Authored-By: kim <89579420+NyaaaWhatsUpDoc@users.noreply.github.com>

* [chore] Less escaped double-quotes

* [chore] Fix help string

---------

Co-authored-by: kim <89579420+NyaaaWhatsUpDoc@users.noreply.github.com>

cmd/gotosocial/common.go

@@ -63,6 +63,7 @@ func preRun(a preRunArgs) error {
 // The idea here is to take a GTSAction and run it with the given
 // context, after initializing any last-minute things like loggers etc.
 func run(ctx context.Context, action action.GTSAction) error {
+	log.SetTimeFormat(config.GetLogTimestampFormat())
 	// Set the global log level from configuration
 	if err := log.ParseLevel(config.GetLogLevel()); err != nil {
 		return fmt.Errorf("error parsing log level: %w", err)

docs/configuration/general.md

@@ -28,6 +28,17 @@ log-db-queries: false
 # Default: true
 log-client-ip: true
 
+# String. Format to use for the timestamp in log lines.
+# If set to the empty string, the timestamp will be
+# ommitted from the logs entirely.
+#
+# The format must be compatible with Go's time.Layout, as
+# documented on https://pkg.go.dev/time#pkg-constants.
+#
+# Examples: [true, false]
+# Default: "02/01/2006 15:04:05.000"
+log-timestamp-format: "02/01/2006 15:04:05.000"
+
 # String. Application name to use internally.
 # Examples: ["My Application","gotosocial"]
 # Default: "gotosocial"

example/config.yaml

@@ -35,6 +35,17 @@ log-db-queries: false
 # Default: true
 log-client-ip: true
 
+# String. Format to use for the timestamp in log lines.
+# If set to the empty string, the timestamp will be
+# ommitted from the logs entirely.
+#
+# The format must be compatible with Go's time.Layout, as
+# documented on https://pkg.go.dev/time#pkg-constants.
+#
+# Examples: [true, false]
+# Default: "02/01/2006 15:04:05.000"
+log-timestamp-format: "02/01/2006 15:04:05.000"
+
 # String. Application name to use internally.
 # Examples: ["My Application","gotosocial"]
 # Default: "gotosocial"

internal/config/config.go

@@ -45,6 +45,7 @@ func fieldtag(field, tag string) string {
 // `go run ./internal/config/gen/ -out ./internal/config/helpers.gen.go`
 type Configuration struct {
 	LogLevel           string   `name:"log-level" usage:"Log level to run at: [trace, debug, info, warn, fatal]"`
+	LogTimestampFormat string   `name:"log-timestamp-format" usage:"Format to use for the log timestamp, as supported by Go's time.Layout"`
 	LogDbQueries       bool     `name:"log-db-queries" usage:"Log database queries verbosely when log-level is trace or debug"`
 	LogClientIP        bool     `name:"log-client-ip" usage:"Include the client IP in logs"`
 	ApplicationName    string   `name:"application-name" usage:"Name of the application, used in various places internally"`

internal/config/defaults.go

@@ -28,6 +28,7 @@
 // if you use this, you will still need to set Host, and, if desired, ConfigPath.
 var Defaults = Configuration{
 	LogLevel:           "info",
+	LogTimestampFormat: "02/01/2006 15:04:05.000",
 	LogDbQueries:       false,
 	ApplicationName:    "gotosocial",
 	LandingPageUser:    "",

internal/config/flags.go

@@ -38,6 +38,7 @@ func (s *ConfigState) AddGlobalFlags(cmd *cobra.Command) {
 		cmd.PersistentFlags().String(AccountDomainFlag(), cfg.AccountDomain, fieldtag("AccountDomain", "usage"))
 		cmd.PersistentFlags().String(ProtocolFlag(), cfg.Protocol, fieldtag("Protocol", "usage"))
 		cmd.PersistentFlags().String(LogLevelFlag(), cfg.LogLevel, fieldtag("LogLevel", "usage"))
+		cmd.PersistentFlags().String(LogTimestampFormatFlag(), cfg.LogTimestampFormat, fieldtag("LogTimestampFormat", "usage"))
 		cmd.PersistentFlags().Bool(LogDbQueriesFlag(), cfg.LogDbQueries, fieldtag("LogDbQueries", "usage"))
 		cmd.PersistentFlags().String(ConfigPathFlag(), cfg.ConfigPath, fieldtag("ConfigPath", "usage"))
 

internal/config/helpers.gen.go

@@ -49,6 +49,31 @@ func GetLogLevel() string { return global.GetLogLevel() }
 // SetLogLevel safely sets the value for global configuration 'LogLevel' field
 func SetLogLevel(v string) { global.SetLogLevel(v) }
 
+// GetLogTimestampFormat safely fetches the Configuration value for state's 'LogTimestampFormat' field
+func (st *ConfigState) GetLogTimestampFormat() (v string) {
+	st.mutex.RLock()
+	v = st.config.LogTimestampFormat
+	st.mutex.RUnlock()
+	return
+}
+
+// SetLogTimestampFormat safely sets the Configuration value for state's 'LogTimestampFormat' field
+func (st *ConfigState) SetLogTimestampFormat(v string) {
+	st.mutex.Lock()
+	defer st.mutex.Unlock()
+	st.config.LogTimestampFormat = v
+	st.reloadToViper()
+}
+
+// LogTimestampFormatFlag returns the flag name for the 'LogTimestampFormat' field
+func LogTimestampFormatFlag() string { return "log-timestamp-format" }
+
+// GetLogTimestampFormat safely fetches the value for global configuration 'LogTimestampFormat' field
+func GetLogTimestampFormat() string { return global.GetLogTimestampFormat() }
+
+// SetLogTimestampFormat safely sets the value for global configuration 'LogTimestampFormat' field
+func SetLogTimestampFormat(v string) { global.SetLogTimestampFormat(v) }
+
 // GetLogDbQueries safely fetches the Configuration value for state's 'LogDbQueries' field
 func (st *ConfigState) GetLogDbQueries() (v bool) {
 	st.mutex.RLock()

internal/log/log.go

@@ -23,7 +23,6 @@
 	"log/syslog"
 	"os"
 	"strings"
-	"sync/atomic"
 	"syscall"
 	"time"
 
@@ -33,7 +32,7 @@
 
 var (
 	// loglvl is the currently set logging level.
-	loglvl atomic.Uint32
+	loglvl level.LEVEL
 
 	// lvlstrs is the lookup table of log levels to strings.
 	lvlstrs = level.Default()
@@ -41,8 +40,9 @@
 	// syslog output, only set if enabled.
 	sysout *syslog.Writer
 
-	// timefmt is the logging time format used.
-	timefmt = "02/01/2006 15:04:05.000"
+	// timefmt is the logging time format used, which includes
+	// the full field and required quoting
+	timefmt = `timestamp="02/01/2006 15:04:05.000" `
 
 	// ctxhooks allows modifying log content based on context.
 	ctxhooks []func(context.Context, []kv.Field) []kv.Field
@@ -55,12 +55,26 @@ func Hook(hook func(ctx context.Context, kvs []kv.Field) []kv.Field) {
 
 // Level returns the currently set log level.
 func Level() level.LEVEL {
-	return level.LEVEL(loglvl.Load())
+	return loglvl
 }
 
 // SetLevel sets the max logging level.
 func SetLevel(lvl level.LEVEL) {
-	loglvl.Store(uint32(lvl))
+	loglvl = lvl
+}
+
+// TimeFormat returns the currently-set timestamp format.
+func TimeFormat() string {
+	return timefmt
+}
+
+// SetTimeFormat sets the timestamp format to the given string.
+func SetTimeFormat(format string) {
+	if format == "" {
+		timefmt = format
+		return
+	}
+	timefmt = `timestamp="` + format + `" `
 }
 
 // New starts a new log entry.
@@ -164,10 +178,8 @@ func printf(depth int, fields []kv.Field, s string, a ...interface{}) {
 	// Acquire buffer
 	buf := getBuf()
 
-	// Append formatted timestamp
-	buf.B = append(buf.B, `timestamp="`...)
+	// Append formatted timestamp according to `timefmt`
 	buf.B = time.Now().AppendFormat(buf.B, timefmt)
-	buf.B = append(buf.B, `" `...)
 
 	// Append formatted caller func
 	buf.B = append(buf.B, `func=`...)
@@ -217,10 +229,8 @@ func logf(ctx context.Context, depth int, lvl level.LEVEL, fields []kv.Field, s
 	// Acquire buffer
 	buf := getBuf()
 
-	// Append formatted timestamp
-	buf.B = append(buf.B, `timestamp="`...)
+	// Append formatted timestamp according to `timefmt`
 	buf.B = time.Now().AppendFormat(buf.B, timefmt)
-	buf.B = append(buf.B, `" `...)
 
 	// Append formatted caller func
 	buf.B = append(buf.B, `func=`...)

internal/log/syslog_test.go

@@ -71,6 +71,22 @@ func (suite *SyslogTestSuite) TestSyslog() {
 	suite.Regexp(regexp.MustCompile(`timestamp=.* func=.* level=INFO msg="this is a test of the emergency broadcast system!"`), entry["content"])
 }
 
+func (suite *SyslogTestSuite) TestSyslogDisableTimestamp() {
+	// Get the current format.
+	timefmt := log.TimeFormat()
+
+	// Set an empty timestamp.
+	log.SetTimeFormat("")
+
+	// Set old timestamp on return.
+	defer log.SetTimeFormat(timefmt)
+
+	log.Info(nil, "this is a test of the emergency broadcast system!")
+
+	entry := <-suite.syslogChannel
+	suite.Regexp(regexp.MustCompile(`func=.* level=INFO msg="this is a test of the emergency broadcast system!"`), entry["content"])
+}
+
 func (suite *SyslogTestSuite) TestSyslogLongMessage() {
 	log.Warn(nil, longMessage)
 

test/envparsing.sh

@@ -86,6 +86,7 @@ EXPECT=$(cat << "EOF"
     "log-client-ip": false,
     "log-db-queries": true,
     "log-level": "info",
+    "log-timestamp-format": "banana",
     "media-description-max-chars": 5000,
     "media-description-min-chars": 69,
     "media-emoji-local-max-size": 420,
@@ -155,6 +156,7 @@ EOF
 # Set all the environment variables to 
 # ensure that these are parsed without panic
 OUTPUT=$(GTS_LOG_LEVEL='info' \
+GTS_LOG_TIMESTAMP_FORMAT="banana" \
 GTS_LOG_DB_QUERIES=true \
 GTS_LOG_CLIENT_IP=false \
 GTS_APPLICATION_NAME=gts \

testrig/config.go

@@ -34,6 +34,7 @@ func InitTestConfig() {
 
 var testDefaults = config.Configuration{
 	LogLevel:           "info",
+	LogTimestampFormat: "02/01/2006 15:04:05.000",
 	LogDbQueries:       true,
 	ApplicationName:    "gotosocial",
 	LandingPageUser:    "",

testrig/log.go

@@ -26,6 +26,7 @@
 
 // InitTestLog sets the global logger to trace level for logging
 func InitTestLog() {
+	log.SetTimeFormat(config.GetLogTimestampFormat())
 	// Set the global log level from configuration
 	if err := log.ParseLevel(config.GetLogLevel()); err != nil {
 		log.Panicf(nil, "error parsing log level: %v", err)