RSDK-9752: Add -log-file to viam-server. (viamrobotics#4716)

Author: dgottlieb

go.mod

@@ -77,7 +77,7 @@ require (
 	go.uber.org/zap v1.27.0
 	go.viam.com/api v0.1.380
 	go.viam.com/test v1.2.4
-	go.viam.com/utils v0.1.120
+	go.viam.com/utils v0.1.123
 	goji.io v2.0.2+incompatible
 	golang.org/x/image v0.19.0
 	golang.org/x/mobile v0.0.0-20240112133503-c713f31d574b
@@ -94,6 +94,7 @@ require (
 	google.golang.org/grpc v1.66.0
 	google.golang.org/grpc/cmd/protoc-gen-go-grpc v1.2.0
 	google.golang.org/protobuf v1.35.1
+	gopkg.in/natefinch/lumberjack.v2 v2.2.1
 	gopkg.in/src-d/go-billy.v4 v4.3.2
 	gorgonia.org/tensor v0.9.24
 	gotest.tools/gotestsum v1.10.0

go.sum

@@ -1517,8 +1517,8 @@ go.viam.com/api v0.1.380 h1:VgRHDlPBku+kjIp4omxmPNmRVZezytFUUOFJ2xpRFR8=
 go.viam.com/api v0.1.380/go.mod h1:g5eipXHNm0rQmW7DWya6avKcmzoypLmxnMlAaIsE5Ls=
 go.viam.com/test v1.2.4 h1:JYgZhsuGAQ8sL9jWkziAXN9VJJiKbjoi9BsO33TW3ug=
 go.viam.com/test v1.2.4/go.mod h1:zI2xzosHdqXAJ/kFqcN+OIF78kQuTV2nIhGZ8EzvaJI=
-go.viam.com/utils v0.1.120 h1:qwHt053zgcg6HtdDpP6Aj6lkmxZYyL1w6d43Ef18uso=
-go.viam.com/utils v0.1.120/go.mod h1:g1CaEkf7aJCrSI/Sfkx+6cBS1+Y3fPT2pvMQbp7TTBI=
+go.viam.com/utils v0.1.123 h1:0nxG3Rp9MmFn+qFbPQ4qSptz+hvm9MENbPXvKUBgRqU=
+go.viam.com/utils v0.1.123/go.mod h1:g1CaEkf7aJCrSI/Sfkx+6cBS1+Y3fPT2pvMQbp7TTBI=
 go4.org/unsafe/assume-no-moving-gc v0.0.0-20230525183740-e7c30c78aeb2 h1:WJhcL4p+YeDxmZWg141nRm7XC8IDmhz7lk5GpadO1Sg=
 go4.org/unsafe/assume-no-moving-gc v0.0.0-20230525183740-e7c30c78aeb2/go.mod h1:FftLjUGFEDu5k8lt0ddY+HcrH/qU/0qk+H8j9/nTl3E=
 gocv.io/x/gocv v0.25.0/go.mod h1:Rar2PS6DV+T4FL+PM535EImD/h13hGVaHhnCu1xarBs=
@@ -2057,6 +2057,8 @@ gopkg.in/gcfg.v1 v1.2.3/go.mod h1:yesOnuUOFQAhST5vPY4nbZsb/huCgGGXlipJsBn0b3o=
 gopkg.in/ini.v1 v1.51.0/go.mod h1:pNLf8WUiyNEtQjuu5G5vTm06TEv9tsIgeAvK8hOrP4k=
 gopkg.in/ini.v1 v1.67.0 h1:Dgnx+6+nfE+IfzjUEISNeydPJh9AXNNsWbGP9KzCsOA=
 gopkg.in/ini.v1 v1.67.0/go.mod h1:pNLf8WUiyNEtQjuu5G5vTm06TEv9tsIgeAvK8hOrP4k=
+gopkg.in/natefinch/lumberjack.v2 v2.2.1 h1:bBRl1b0OH9s/DuPhuXpNl+VtCaJXFZ5/uEFST95x9zc=
+gopkg.in/natefinch/lumberjack.v2 v2.2.1/go.mod h1:YD8tP3GAjkrDg1eZH7EGmyESg/lsYskCTPBJVb9jqSc=
 gopkg.in/resty.v1 v1.12.0/go.mod h1:mDo4pnntr5jdWRML875a/NmxYqAlA73dVijT2AXvQQo=
 gopkg.in/square/go-jose.v2 v2.6.0 h1:NGk74WTnPKBNUhNzQX7PYcTLUjoq7mzKk2OKbvwk2iI=
 gopkg.in/square/go-jose.v2 v2.6.0/go.mod h1:M9dMgbHiYLoDGQrXy7OpJDJWiKiU//h+vD76mk0e1AI=

logging/appender.go

@@ -7,6 +7,7 @@ import (
 	"strings"
 
 	"go.uber.org/zap/zapcore"
+	"gopkg.in/natefinch/lumberjack.v2"
 )
 
 // DefaultTimeFormatStr is the default time format string for log appenders.
@@ -36,6 +37,28 @@ func NewWriterAppender(writer io.Writer) ConsoleAppender {
 	return ConsoleAppender{writer}
 }
 
+// NewFileAppender will create an Appender that writes output to a log file. Log rotation will be
+// enabled such that restarts of the viam-server with the same filename will move the old file out
+// of the way. The `io.Closer` can be used to eventually close the opened log file.
+func NewFileAppender(filename string) (Appender, io.Closer) {
+	logger := &lumberjack.Logger{
+		Filename: filename,
+		// 1 Terabyte -- basically infinite. Don't rollover on size. Just restarts.
+		MaxSize: 1024 * 1024,
+	}
+
+	// Dan: If we're restarting, explicitly call `Rotate` to write to a different file. This is a
+	// convention I think is nice, but by no means a correctness requirement.
+	if err := logger.Rotate(); err != nil {
+		Global().Fatal("Error creating log file: ", err)
+	}
+
+	// We only have `NewFileAppender` return an io.Closer, rather than `NewWriterAppender` because
+	// `NewWriterAppender` accepts stdout from `NewStdoutAppender`. And I'm not certain that it's a
+	// good idea to be calling `stdout.Close`.
+	return NewWriterAppender(logger), logger
+}
+
 // ZapcoreFieldsToJSON will serialize the Field objects into a JSON map of key/value pairs. It's
 // unclear what circumstances will result in an error being returned.
 func ZapcoreFieldsToJSON(fields []zapcore.Field) (string, error) {

logging/logging.go

@@ -131,6 +131,24 @@ func NewBlankLogger(name string) Logger {
 	return logger
 }
 
+// NewBlankLoggerWithRegistry returns a new logger that outputs Debug+ logs in UTC, but without any
+// pre-existing appenders/outputs. It also returns the logger `Registry`.
+func NewBlankLoggerWithRegistry(name string) (Logger, *Registry) {
+	logger := &impl{
+		name:                     name,
+		level:                    NewAtomicLevelAt(DEBUG),
+		appenders:                []Appender{},
+		registry:                 newRegistry(),
+		testHelper:               func() {},
+		recentMessageCounts:      make(map[string]int),
+		recentMessageEntries:     make(map[string]LogEntry),
+		recentMessageWindowStart: time.Now(),
+	}
+
+	logger.registry.registerLogger(name, logger)
+	return logger, logger.registry
+}
+
 // NewTestLogger returns a new logger that outputs Debug+ logs to stdout in local time.
 func NewTestLogger(tb testing.TB) Logger {
 	logger, _ := NewObservedTestLogger(tb)

web/server/entrypoint.go

@@ -51,6 +51,7 @@ type Arguments struct {
 	DisableMulticastDNS        bool   `flag:"disable-mdns,usage=disable server discovery through multicast DNS"`
 	DumpResourcesPath          string `flag:"dump-resources,usage=dump all resource registrations as json to the provided file path"`
 	EnableFTDC                 bool   `flag:"ftdc,default=true,usage=enable fulltime data capture for diagnostics"`
+	OutputLogFile              string `flag:"log-file,usage=write logs to a file with log rotation"`
 }
 
 type robotServer struct {
@@ -70,6 +71,9 @@ func logViamEnvVariables(logger logging.Logger) {
 	if value, exists := os.LookupEnv("VIAM_MODULE_STARTUP_TIMEOUT"); exists {
 		viamEnvVariables = append(viamEnvVariables, "VIAM_MODULE_STARTUP_TIMEOUT", value)
 	}
+	if value, exists := os.LookupEnv("CWD"); exists {
+		viamEnvVariables = append(viamEnvVariables, "CWD", value)
+	}
 	if rutils.PlatformHomeDir() != "" {
 		viamEnvVariables = append(viamEnvVariables, "HOME", rutils.PlatformHomeDir())
 	}
@@ -115,7 +119,22 @@ func RunServer(ctx context.Context, args []string, _ logging.Logger) (err error)
 		return dumpResourceRegistrations(argsParsed.DumpResourcesPath)
 	}
 
-	logger, registry := logging.NewLoggerWithRegistry("rdk")
+	logger, registry := logging.NewBlankLoggerWithRegistry("rdk")
+	// Dan: We changed from a constructor that defaulted to INFO to `NewBlankLoggerWithRegistry`
+	// which defaults to DEBUG. We pessimistically set the level to INFO to ensure parity. Though I
+	// expect `InitLoggingSettings` will always put the logger into the right state without any
+	// observable side-effects.
+	logger.SetLevel(logging.INFO)
+	if argsParsed.OutputLogFile != "" {
+		logWriter, closer := logging.NewFileAppender(argsParsed.OutputLogFile)
+		defer func() {
+			utils.UncheckedError(closer.Close())
+		}()
+		logger.AddAppender(logWriter)
+	} else {
+		logger.AddAppender(logging.NewStdoutAppender())
+	}
+
 	logging.RegisterEventLogger(logger)
 	logging.ReplaceGlobal(logger)
 	config.InitLoggingSettings(logger, argsParsed.Debug)