Repository: nats-io/nats-server (go)

Issue:
Configure log timestamp as UTC
## Feature Request

Log timestamp can be enabled or disabled (default enabled), but timestamp is always in the host's currently configured timezone (e.g. PST).  The timezone is not recorded in the timestamp format.

Users would benefit from an option to log timestamp as UTC regardless of host's currently configured timezone.

#### Use Case:

Logs from multiple servers are scraped into a central log aggregator service where timezone normalization is needed or required.

#### Proposed Change:

Add a server configuration option (not default to preserve back compatibility) to always log timestamps (if enabled) as normalized UTC.

#### Who Benefits From The Change(s)?

Users who aggregate server logs from multiple hosts that may not always be uniformly configured as UTC timezone at host level.

#### Alternative Approaches

Output timestamp in format that preserves timezone information which could allow log aggregators to normalize downstream as required.


Pull request:
Add `logtime_utc` option
Fixes #3826 by adding the `logtime_utc` configuration option for both the stdout and the file logger.

Signed-off-by: Neil Twigg <neil@nats.io>

Patch:
diff --git a/logger/log.go b/logger/log.go
index 57cab62f..b2716967 100644
--- a/logger/log.go
+++ b/logger/log.go
@@ -38,13 +38,37 @@ type Logger struct {
 	fl         *fileLogger
 }
 
-// NewStdLogger creates a logger with output directed to Stderr
-func NewStdLogger(time, debug, trace, colors, pid bool) *Logger {
+type LogOption interface {
+	isLoggerOption()
+}
+
+// LogUTC controls whether timestamps in the log output should be UTC or local time.
+type LogUTC bool
+
+func (l LogUTC) isLoggerOption() {}
+
+func logFlags(time bool, opts ...LogOption) int {
 	flags := 0
 	if time {
 		flags = log.LstdFlags | log.Lmicroseconds
 	}
 
+	for _, opt := range opts {
+		switch v := opt.(type) {
+		case LogUTC:
+			if time && bool(v) {
+				flags |= log.LUTC
+			}
+		}
+	}
+
+	return flags
+}
+
+// NewStdLogger creates a logger with output directed to Stderr
+func NewStdLogger(time, debug, trace, colors, pid bool, opts ...LogOption) *Logger {
+	flags := logFlags(time, opts...)
+
 	pre := ""
 	if pid {
 		pre = pidPrefix()
@@ -66,11 +90,8 @@ func NewStdLogger(time, debug, trace, colors, pid bool) *Logger {
 }
 
 // NewFileLogger creates a logger with output directed to a file
-func NewFileLogger(filename string, time, debug, trace, pid bool) *Logger {
-	flags := 0
-	if time {
-		flags = log.LstdFlags | log.Lmicroseconds
-	}
+func NewFileLogger(filename string, time, debug, trace, pid bool, opts ...LogOption) *Logger {
+	flags := logFlags(time, opts...)
 
 	pre := ""
 	if pid {
diff --git a/server/configs/reload/reload.conf b/server/configs/reload/reload.conf
index 613033a7..068500b3 100644
--- a/server/configs/reload/reload.conf
+++ b/server/configs/reload/reload.conf
@@ -6,6 +6,7 @@ port: 2233
 debug:         true # enable on reload
 trace:         true # enable on reload
 logtime:       true # enable on reload
+logtime_utc:   true # enable on reload
 
 log_file:         "nats-server.log" # change on reload
 pid_file:         "nats-server.pid" # change on reload
diff --git a/server/log.go b/server/log.go
index 143a56ab..60ca41c2 100644
--- a/server/log.go
+++ b/server/log.go
@@ -66,7 +66,7 @@ func (s *Server) ConfigureLogger() {
 	}
 
 	if opts.LogFile != "" {
-		log = srvlog.NewFileLogger(opts.LogFile, opts.Logtime, opts.Debug, opts.Trace, true)
+		log = srvlog.NewFileLogger(opts.LogFile, opts.Logtime, opts.Debug, opts.Trace, true, srvlog.LogUTC(opts.LogtimeUTC))
 		if opts.LogSizeLimit > 0 {
 			if l, ok := log.(*srvlog.Logger); ok {
 				l.SetSizeLimit(opts.LogSizeLimit)
@@ -84,7 +84,7 @@ func (s *Server) ConfigureLogger() {
 		if err != nil || (stat.Mode()&os.ModeCharDevice) == 0 {
 			colors = false
 		}
-		log = srvlog.NewStdLogger(opts.Logtime, opts.Debug, opts.Trace, colors, true)
+		log = srvlog.NewStdLogger(opts.Logtime, opts.Debug, opts.Trace, colors, true, srvlog.LogUTC(opts.LogtimeUTC))
 	}
 
 	s.SetLoggerV2(log, opts.Debug, opts.Trace, opts.TraceVerbose)
@@ -154,8 +154,11 @@ func (s *Server) ReOpenLogFile() {
 	if opts.LogFile == "" {
 		s.Noticef("File log re-open ignored, not a file logger")
 	} else {
-		fileLog := srvlog.NewFileLogger(opts.LogFile,
-			opts.Logtime, opts.Debug, opts.Trace, true)
+		fileLog := srvlog.NewFileLogger(
+			opts.LogFile, opts.Logtime,
+			opts.Debug, opts.Trace, true,
+			srvlog.LogUTC(opts.LogtimeUTC),
+		)
 		s.SetLogger(fileLog, opts.Debug, opts.Trace)
 		if opts.LogSizeLimit > 0 {
 			fileLog.SetSizeLimit(opts.LogSizeLimit)
diff --git a/server/opts.go b/server/opts.go
index cf956c4e..904c9b87 100644
--- a/server/opts.go
+++ b/server/opts.go
@@ -234,6 +234,7 @@ type Options struct {
 	NoHeaderSupport       bool          `json:"-"`
 	DisableShortFirstPing bool          `json:"-"`
 	Logtime               bool          `json:"-"`
+	LogtimeUTC            bool          `json:"-"`
 	MaxConn               int           `json:"max_connections"`
 	MaxSubs               int           `json:"max_subscriptions,omitempty"`
 	MaxSubTokens          uint8         `json:"-"`
@@ -805,6 +806,9 @@ func (o *Options) processConfigFileLine(k string, v interface{}, errors *[]error
 	case "logtime":
 		o.Logtime = v.(bool)
 		trackExplicitVal(o, &o.inConfig, "Logtime", o.Logtime)
+	case "logtime_utc":
+		o.LogtimeUTC = v.(bool)
+		trackExplicitVal(o, &o.inConfig, "LogtimeUTC", o.LogtimeUTC)
 	case "mappings", "maps":
 		gacc := NewAccount(globalAccountName)
 		o.Accounts = append(o.Accounts, gacc)
@@ -4805,6 +4809,7 @@ func ConfigureOptions(fs *flag.FlagSet, args []string, printVersion, printHelp,
 	fs.BoolVar(&dbgAndTrcAndVerboseTrc, "DVV", false, "Enable Debug and Verbose Trace logging. (Traces system account as well)")
 	fs.BoolVar(&opts.Logtime, "T", true, "Timestamp log entries.")
 	fs.BoolVar(&opts.Logtime, "logtime", true, "Timestamp log entries.")
+	fs.BoolVar(&opts.LogtimeUTC, "logtime_utc", true, "Timestamps in UTC instead of local timezone.")
 	fs.StringVar(&opts.Username, "user", _EMPTY_, "Username required for connection.")
 	fs.StringVar(&opts.Password, "pass", _EMPTY_, "Password required for connection.")
 	fs.StringVar(&opts.Authorization, "auth", _EMPTY_, "Authorization token required for connection.")
diff --git a/server/reload.go b/server/reload.go
index b25b43d6..7f083066 100644
--- a/server/reload.go
+++ b/server/reload.go
@@ -162,6 +162,17 @@ func (l *logtimeOption) Apply(server *Server) {
 	server.Noticef("Reloaded: logtime = %v", l.newValue)
 }
 
+// logtimeUTCOption implements the option interface for the `logtime_utc` setting.
+type logtimeUTCOption struct {
+	loggingOption
+	newValue bool
+}
+
+// Apply is a no-op because logging will be reloaded after options are applied.
+func (l *logtimeUTCOption) Apply(server *Server) {
+	server.Noticef("Reloaded: logtime_utc = %v", l.newValue)
+}
+
 // logfileOption implements the option interface for the `log_file` setting.
 type logfileOption struct {
 	loggingOption
@@ -1017,6 +1028,8 @@ func (s *Server) diffOptions(newOpts *Options) ([]option, error) {
 			diffOpts = append(diffOpts, &debugOption{newValue: newValue.(bool)})
 		case "logtime":
 			diffOpts = append(diffOpts, &logtimeOption{newValue: newValue.(bool)})
+		case "logtimeutc":
+			diffOpts = append(diffOpts, &logtimeUTCOption{newValue: newValue.(bool)})
 		case "logfile":
 			diffOpts = append(diffOpts, &logfileOption{newValue: newValue.(string)})
 		case "syslog":


Test patch:
diff --git a/logger/log_test.go b/logger/log_test.go
index a8d13f39..f49c07e6 100644
--- a/logger/log_test.go
+++ b/logger/log_test.go
@@ -125,7 +125,7 @@ func TestFileLogger(t *testing.T) {
 	file = createFileAtDir(t, tmpDir, "nats-server:log_")
 	file.Close()
 
-	logger = NewFileLogger(file.Name(), true, true, true, true)
+	logger = NewFileLogger(file.Name(), true, false, true, true)
 	defer logger.Close()
 	logger.Errorf("foo")
 
diff --git a/server/log_test.go b/server/log_test.go
index 7cf9b8c5..3ea4b1e1 100644
--- a/server/log_test.go
+++ b/server/log_test.go
@@ -101,7 +101,7 @@ func TestReOpenLogFile(t *testing.T) {
 
 	// Set a File log
 	s.opts.LogFile = filepath.Join(t.TempDir(), "test.log")
-	fileLog := logger.NewFileLogger(s.opts.LogFile, s.opts.Logtime, s.opts.Debug, s.opts.Trace, true)
+	fileLog := logger.NewFileLogger(s.opts.LogFile, s.opts.Logtime, s.opts.Debug, s.opts.Trace, true, logger.LogUTC(s.opts.LogtimeUTC))
 	s.SetLogger(fileLog, false, false)
 	// Add some log
 	expectedStr := "This is a Notice"
diff --git a/server/reload_test.go b/server/reload_test.go
index 35712b61..06762483 100644
--- a/server/reload_test.go
+++ b/server/reload_test.go
@@ -308,6 +308,9 @@ func TestConfigReload(t *testing.T) {
 	if !updated.Logtime {
 		t.Fatal("Expected Logtime to be true")
 	}
+	if !updated.LogtimeUTC {
+		t.Fatal("Expected LogtimeUTC to be true")
+	}
 	if runtime.GOOS != "windows" {
 		if !updated.Syslog {
 			t.Fatal("Expected Syslog to be true")
diff --git a/server/signal_test.go b/server/signal_test.go
index 5520bb6b..1127546d 100644
--- a/server/signal_test.go
+++ b/server/signal_test.go
@@ -44,7 +44,7 @@ func TestSignalToReOpenLogFile(t *testing.T) {
 	defer s.Shutdown()
 
 	// Set the file log
-	fileLog := logger.NewFileLogger(s.opts.LogFile, s.opts.Logtime, s.opts.Debug, s.opts.Trace, true)
+	fileLog := logger.NewFileLogger(s.opts.LogFile, s.opts.Logtime, s.opts.Debug, s.opts.Trace, true, logger.LogUTC(s.opts.LogtimeUTC))
 	s.SetLogger(fileLog, false, false)
 
 	// Add a trace