diff --git a/README.md b/README.md index a1caea9..661a797 100644 --- a/README.md +++ b/README.md @@ -83,6 +83,11 @@ The configuration file is the heart of Silver. Here is a comprehensive example w "LogFileMaxSizeMb": 50, "LogFileMaxBackupFiles": 5, + // Custom format for log timestamps (e.g., "2006-01-02 15:04:05.000"). + // If set, this overrides the default timestamp format. + // This is in GO format, see https://pkg.go.dev/time#Layout + "LogFileTimestampFormat": "2006-01-02 15:04:05.000000", + // File to store the current main service PID. "PidFile": "${ServiceRoot}/${ServiceName}.pid", @@ -434,4 +439,3 @@ This project is licensed under the MIT Licence. See the `LICENSE` file for detai ## **About This Project** Silver is an open-source project actively maintained and supported by PaperCut Software. It is battle-tested technology, used in production to manage server and desktop components for millions of laptops and servers running [PaperCut's print management software](https://www.papercut.com/) for nearly a decade. Silver is a better tool thanks to the collective effort of its community. A big thank you to everyone who has contributed their time, ideas, and code to the project. - diff --git a/conf/examples/silver-kitchen-sink.conf b/conf/examples/silver-kitchen-sink.conf index 0aa04d0..60eb173 100644 --- a/conf/examples/silver-kitchen-sink.conf +++ b/conf/examples/silver-kitchen-sink.conf @@ -9,6 +9,7 @@ "LogFile": "${ServiceName}.log", "LogFileMaxSizeMb": 200, "LogFileMaxBackupFiles": 5, + "LogFileTimestampFormat": "2006-01-02 15:04:05", "PidFile": "${ServiceName}.pid" }, "EnvironmentVars": { diff --git a/conf/examples/silver-log-stdout.conf b/conf/examples/silver-log-stdout.conf index 197e34c..de6e4f6 100644 --- a/conf/examples/silver-log-stdout.conf +++ b/conf/examples/silver-log-stdout.conf @@ -4,7 +4,8 @@ "Description": "Only does one thing, but does it well!" }, "ServiceConfig": { - "LogFile": "os.stdout" + "LogFile": "os.stdout", + "LogFileTimestampFormat": "2006-01-02 15:04:05" }, "Services": [ { diff --git a/lib/logging/logging.go b/lib/logging/logging.go index b9ab732..d06f92b 100644 --- a/lib/logging/logging.go +++ b/lib/logging/logging.go @@ -64,6 +64,22 @@ func init() { changeOwnerOfFileFunc = changeOwnerOfFile } +type logWriter struct { + io.Writer + timeformat string +} + +// custom Write to add timestamps with custom format +func (w logWriter) Write(bytes []byte) (int, error) { + timestamp := time.Now().Format(w.timeformat) + " " + n1, err := io.WriteString(w.Writer, timestamp) + if err != nil { + return n1, err + } + n2, err := w.Writer.Write(bytes) + return n1 + n2, err +} + func (f *flusher) run(rf *rollingFile) { tick := time.Tick(f.interval) for { @@ -176,12 +192,12 @@ func openLogFile(name string, owner string) (f *os.File, err error) { } // NewFileLogger implements a rolling logger with default maximum size (50Mb) -func NewFileLogger(file string, owner string) (logger *log.Logger) { - return NewFileLoggerWithMaxSize(file, owner, defaultMaxSize, defaultMaxBackupFiles) +func NewFileLogger(file string, owner string, timeformat string) (logger *log.Logger) { + return NewFileLoggerWithMaxSize(file, owner, defaultMaxSize, defaultMaxBackupFiles, timeformat) } // NewFileLoggerWithMaxSize implements a rolling logger with a set size -func NewFileLoggerWithMaxSize(file string, owner string, maxSize int64, maxBackupFiles int) (logger *log.Logger) { +func NewFileLoggerWithMaxSize(file string, owner string, maxSize int64, maxBackupFiles int, timeformat string) (logger *log.Logger) { rf, err := newRollingFile(file, owner, maxSize, maxBackupFiles) // This trick ensures that the flusher goroutine does not keep // the returned wrapper object from being garbage collected. When it is @@ -190,7 +206,13 @@ func NewFileLoggerWithMaxSize(file string, owner string, maxSize int64, maxBacku rfWrapper := &rollingFileWrapper{rf} runtime.SetFinalizer(rfWrapper, stopFlusher) if err == nil { - logger = log.New(rfWrapper, "", log.Ldate|log.Ltime) + var writer io.Writer = rfWrapper + flags := log.Ldate | log.Ltime + if timeformat != "" { + writer = logWriter{Writer: rfWrapper, timeformat: timeformat} + flags = 0 + } + logger = log.New(writer, "", flags) } else { fmt.Fprintf(os.Stderr, "WARNING: Unable to set up log file: %v\n", err) logger = NewNilLogger() @@ -213,13 +235,25 @@ func NewNilLogger() *log.Logger { } // NewConsoleErrorLogger is a basic logger to Stderr -func NewConsoleErrorLogger() (logger *log.Logger) { - logger = log.New(os.Stderr, "", log.Ldate|log.Ltime) +func NewConsoleErrorLogger(timeformat string) (logger *log.Logger) { + var writer io.Writer = os.Stderr + flags := log.Ldate | log.Ltime + if timeformat != "" { + writer = logWriter{Writer: os.Stderr, timeformat: timeformat} + flags = 0 + } + logger = log.New(writer, "", flags) return logger } // NewConsoleLogger is a basic logger to Stdout -func NewConsoleLogger() (logger *log.Logger) { - logger = log.New(os.Stdout, "", log.Ldate|log.Ltime) +func NewConsoleLogger(timeformat string) (logger *log.Logger) { + var writer io.Writer = os.Stdout + flags := log.Ldate | log.Ltime + if timeformat != "" { + writer = logWriter{Writer: os.Stdout, timeformat: timeformat} + flags = 0 + } + logger = log.New(writer, "", flags) return logger } diff --git a/lib/logging/logging_test.go b/lib/logging/logging_test.go index 501ace6..960d90c 100644 --- a/lib/logging/logging_test.go +++ b/lib/logging/logging_test.go @@ -3,6 +3,7 @@ package logging import ( "fmt" "os" + "regexp" "strings" "testing" "time" @@ -11,13 +12,13 @@ import ( func TestStandardLogging(t *testing.T) { lname := fmt.Sprintf("%s/test-standard-log-%d.log", os.TempDir(), time.Now().Unix()) - logger := NewFileLogger(lname, "") + logger := NewFileLogger(lname, "", "") defer func() { os.Remove(lname) }() msg := "TestStandardLogging" - logger.Printf(msg) + logger.Print(msg) CloseAllOpenFileLoggers() output, err := os.ReadFile(lname) @@ -25,8 +26,42 @@ func TestStandardLogging(t *testing.T) { t.Errorf("Unable to read file: %v", err) } - if !strings.Contains(string(output), msg) { - t.Errorf("Expected '%s', got '%s'", msg, output) + outstr := string(output) + // Expect format: YYYY-MM-DD HH:MM:SS + re := regexp.MustCompile(`^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} `) + if !re.MatchString(outstr) { + t.Errorf("expected timestamp prefix, got: %q", outstr) + } + if !strings.Contains(outstr, msg) { + t.Errorf("Expected '%s', got '%s'", msg, outstr) + } +} + +func TestStandardTwelveHourLogging(t *testing.T) { + lname := fmt.Sprintf("%s/test-standard-log-%d.log", os.TempDir(), time.Now().Unix()) + + logger := NewFileLogger(lname, "", "2006/01/02 03:04:05 PM") + defer func() { + os.Remove(lname) + }() + + msg := "TestStandardLogging" + logger.Print(msg) + CloseAllOpenFileLoggers() + + output, err := os.ReadFile(lname) + if err != nil { + t.Errorf("Unable to read file: %v", err) + } + + outstr := string(output) + // Expect format: YYYY/MM/DD HH:MM:SS [AM|PM] + re := regexp.MustCompile(`^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} [APM]{2} `) + if !re.MatchString(outstr) { + t.Errorf("expected timestamp prefix, got: %q", outstr) + } + if !strings.Contains(outstr, msg) { + t.Errorf("Expected '%s', got '%s'", msg, outstr) } } @@ -34,7 +69,7 @@ func TestRollingLog(t *testing.T) { lname := fmt.Sprintf("%s/test-rolling-log-%d.log", os.TempDir(), time.Now().Unix()) // Create the logger with log rotation for max 5 backup files. - logger := NewFileLoggerWithMaxSize(lname, "", 1024, 5) + logger := NewFileLoggerWithMaxSize(lname, "", 1024, 5, "2006.01.02 03:04:05 PM") defer func() { // Clean up all the log files after the test. for i := 0; i <= 5; i++ { // Remove the main log file and the 5 backups. @@ -59,8 +94,13 @@ func TestRollingLog(t *testing.T) { if err != nil { t.Errorf("Unable to read file: %v", err) } - if !strings.Contains(string(output), msg) { - t.Errorf("Expected '%s', got '%s'", msg, output) + outputStr := string(output) + if !strings.Contains(outputStr, msg) { + t.Errorf("Expected '%s', got '%s'", msg, outputStr) + } + re := regexp.MustCompile(`^\d{4}.\d{2}.\d{2} \d{2}:\d{2}:\d{2} [APM]{2} `) + if !re.MatchString(outputStr) { + t.Errorf("expected timestamp prefix, got: %q", outputStr) } rolledFileName = fmt.Sprintf("%s.%d", lname, i+1) // lname.1, lname.2, etc. } @@ -74,9 +114,8 @@ func TestRollingLog(t *testing.T) { func TestRollingLogFlush_IsFlushed(t *testing.T) { // Arrange - //lname := fmt.Sprintf("%s/test-flushed-log-%d.log", os.TempDir(), time.Now().Unix()) lname := fmt.Sprintf("test-flushed-log-%d.log", time.Now().Unix()) - logger := NewFileLoggerWithMaxSize(lname, "", 10024, 5) + logger := NewFileLoggerWithMaxSize(lname, "", 10024, 5, "") defer func() { CloseAllOpenFileLoggers() os.Remove(lname) diff --git a/lib/logging/owner_unix_test.go b/lib/logging/owner_unix_test.go index fcfe66f..2267627 100644 --- a/lib/logging/owner_unix_test.go +++ b/lib/logging/owner_unix_test.go @@ -23,7 +23,7 @@ func TestLogIsOwnedByCorrectUser(t *testing.T) { lname := fmt.Sprintf("%s/test-standard-log-%d.log", os.TempDir(), time.Now().Unix()) - logger := NewFileLogger(lname, userName) + logger := NewFileLogger(lname, userName, "") defer func() { os.Remove(lname) }() diff --git a/service/config/config.go b/service/config/config.go index b2273fe..4a607de 100644 --- a/service/config/config.go +++ b/service/config/config.go @@ -40,14 +40,15 @@ type ServiceDescription struct { } type ServiceConfig struct { - StopFile string - ReloadFile string - LogFile string - LogFileMaxSizeMb int64 - LogFileMaxBackupFiles int - PidFile string - UserLevel bool - UserName string + StopFile string + ReloadFile string + LogFile string + LogFileMaxSizeMb int64 + LogFileMaxBackupFiles int + PidFile string + UserLevel bool + UserName string + LogFileTimestampFormat string } type command struct { diff --git a/service/main.go b/service/main.go index ce9e504..88d7109 100644 --- a/service/main.go +++ b/service/main.go @@ -1,13 +1,12 @@ // SILVER - Service Wrapper // -// Copyright (c) 2014-2021 PaperCut Software http://www.papercut.com/ +// Copyright (c) 2014-2025 PaperCut Software http://www.papercut.com/ // Use of this source code is governed by an MIT or GPL Version 2 license. // See the project's LICENSE file for more information. package main import ( "fmt" - "io/ioutil" "log" "os" "path" @@ -106,10 +105,10 @@ func osServiceControl(ctx *context) int { logFile = serviceName + ".log" } if logFile == "os.stdout" { - ctx.logger = logging.NewConsoleLogger() - ctx.errorLogger = logging.NewConsoleErrorLogger() + ctx.logger = logging.NewConsoleLogger(ctx.conf.ServiceConfig.LogFileTimestampFormat) + ctx.errorLogger = logging.NewConsoleErrorLogger(ctx.conf.ServiceConfig.LogFileTimestampFormat) } else { - ctx.logger = logging.NewFileLoggerWithMaxSize(logFile, ctx.conf.ServiceConfig.UserName, maxSize, ctx.conf.ServiceConfig.LogFileMaxBackupFiles) + ctx.logger = logging.NewFileLoggerWithMaxSize(logFile, ctx.conf.ServiceConfig.UserName, maxSize, ctx.conf.ServiceConfig.LogFileMaxBackupFiles, ctx.conf.ServiceConfig.LogFileTimestampFormat) ctx.errorLogger = ctx.logger // use the same output for both stdout and errors } @@ -146,7 +145,7 @@ func osServiceControl(ctx *context) int { pidFile := ctx.conf.ServiceConfig.PidFile if pidFile != "" { - _ = ioutil.WriteFile(pidFile, []byte(fmt.Sprintf("%d\n", os.Getpid())), 0644) + _ = os.WriteFile(pidFile, []byte(fmt.Sprintf("%d\n", os.Getpid())), 0644) } return 0 } @@ -197,7 +196,7 @@ func setupEnvironment(conf *config.Config) { _ = os.Setenv("SILVER_SERVICE_PID", fmt.Sprint(os.Getpid())) // If we have HTTP proxy conf, load this - if b, err := ioutil.ReadFile(proxyConfFile()); err == nil { + if b, err := os.ReadFile(proxyConfFile()); err == nil { proxy := strings.TrimSpace(string(b)) if proxy != "" { _ = os.Setenv("SILVER_HTTP_PROXY", proxy) @@ -215,7 +214,7 @@ func writeProxyConf() error { if err != nil { proxy = "" } - return ioutil.WriteFile(proxyConfFile(), []byte(proxy+"\n"), 0644) + return os.WriteFile(proxyConfFile(), []byte(proxy+"\n"), 0644) } func proxyConfFile() string { @@ -256,7 +255,7 @@ func execCommand(ctx *context, args []string) int { // Append any extra commands cmdConf.Args = append(cmd.Args, args[1:]...) // FIXME: Maybe unit conversion should be in the config layer? - cmdConf.ExecTimeout = (time.Second * time.Duration(cmd.TimeoutSecs)) + cmdConf.ExecTimeout = time.Second * time.Duration(cmd.TimeoutSecs) exitCode, err := cmdutil.Execute(cmdConf) if err != nil { @@ -335,7 +334,7 @@ func doStop(ctx *context) { // Create stop file... another method to signal services to stop. sf := stopFileName(ctx) if sf != "" { - _ = ioutil.WriteFile(sf, nil, 0644) + _ = os.WriteFile(sf, nil, 0644) defer os.Remove(sf) } if ctx.cronManager != nil { diff --git a/service/main_logging_test.go b/service/main_logging_test.go new file mode 100644 index 0000000..7ab33fd --- /dev/null +++ b/service/main_logging_test.go @@ -0,0 +1,93 @@ +package main + +import ( + "os" + "path/filepath" + "regexp" + "runtime" + "strings" + "testing" + + "github.com/papercutsoftware/silver/lib/logging" + "github.com/papercutsoftware/silver/service/config" +) + +func TestLogging_SampleConfigWithDefaultDateFormat(t *testing.T) { + cfg := loadTestConfig(t, "logging-defaultdateformat.conf") + logPath := filepath.Join(t.TempDir(), "no-micro.log") + cfg.ServiceConfig.LogFile = logPath + + logger := logging.NewFileLogger(cfg.ServiceConfig.LogFile, cfg.ServiceConfig.UserName, cfg.ServiceConfig.LogFileTimestampFormat) + t.Cleanup(logging.CloseAllOpenFileLoggers) + + testmessage := "LoggingWithDefaultDateFormat" + logger.Printf("%s %s", testmessage, cfg.ServiceConfig.LogFileTimestampFormat) + logging.CloseAllOpenFileLoggers() + + data, err := os.ReadFile(cfg.ServiceConfig.LogFile) + if err != nil { + t.Fatalf("reading log file: %v", err) + } + line := string(data) + + reDate := regexp.MustCompile(`^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} `) + if !reDate.MatchString(line) { + t.Fatalf("expected default date format without microseconds, got %q", line) + } + + if !strings.Contains(line, testmessage) { + t.Fatalf("expected log line to contain %q, got %q", testmessage, line) + } +} + +func TestLogging_SampleConfigWithMicroseconds(t *testing.T) { + cfg := loadTestConfig(t, "logging-with-microseconds.conf") + logPath := filepath.Join(t.TempDir(), "with-micro.log") + cfg.ServiceConfig.LogFile = logPath + + logger := logging.NewFileLogger(cfg.ServiceConfig.LogFile, cfg.ServiceConfig.UserName, cfg.ServiceConfig.LogFileTimestampFormat) + t.Cleanup(logging.CloseAllOpenFileLoggers) + + testmessage := "LoggingWithMicroseconds" + msg := "%s %s" + logger.Printf(msg, testmessage, cfg.ServiceConfig.LogFileTimestampFormat) + logging.CloseAllOpenFileLoggers() + + data, err := os.ReadFile(cfg.ServiceConfig.LogFile) + if err != nil { + t.Fatalf("reading log file: %v", err) + } + line := string(data) + + re := regexp.MustCompile(`^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{6} `) + if !re.MatchString(line) { + t.Fatalf("expected microsecond precision, got %q", line) + } + + if !strings.Contains(line, testmessage) { + t.Fatalf("expected log line to contain %q, got %q", testmessage, line) + } +} + +func loadTestConfig(t *testing.T, filename string) *config.Config { + t.Helper() + + _, currentFile, _, ok := runtime.Caller(0) + if !ok { + t.Fatal("unable to resolve current file path") + } + baseDir := filepath.Dir(currentFile) + path := filepath.Join(baseDir, "testdata", filename) + + vars := config.ReplacementVars{ + ServiceName: "silver-test", + ServiceRoot: t.TempDir(), + } + + cfg, err := config.LoadConfig(path, vars) + if err != nil { + t.Fatalf("loading config %s: %v", path, err) + } + + return cfg +} diff --git a/service/testdata/logging-defaultdateformat.conf b/service/testdata/logging-defaultdateformat.conf new file mode 100644 index 0000000..b8a16a6 --- /dev/null +++ b/service/testdata/logging-defaultdateformat.conf @@ -0,0 +1,14 @@ +{ + "ServiceDescription": { + "DisplayName": "Test Service With default Date Format", + "Description": "Test config for logging with default date format" + }, + "ServiceConfig": { + "LogFile": "${ServiceName}.log" + }, + "Services": [ + { + "Path": "test/path" + } + ] +} diff --git a/service/testdata/logging-with-microseconds.conf b/service/testdata/logging-with-microseconds.conf new file mode 100644 index 0000000..e1920c9 --- /dev/null +++ b/service/testdata/logging-with-microseconds.conf @@ -0,0 +1,15 @@ +{ + "ServiceDescription": { + "DisplayName": "Test Service With Microseconds", + "Description": "Test config for logging with microsecond precision" + }, + "ServiceConfig": { + "LogFile": "${ServiceName}.log", + "LogFileTimestampFormat": "2006-01-02 15:04:05.000000" + }, + "Services": [ + { + "Path": "test/path" + } + ] +}