From c751aacd33e317efb0dbf436ca0f4162eaa10b01 Mon Sep 17 00:00:00 2001 From: Lars Pehrsson Date: Thu, 18 Sep 2025 08:44:57 +1000 Subject: [PATCH 1/6] Adds custom timestamp format for logging Introduces a configurable option to set custom timestamp formats in log messages, enhancing versatility for log management. Updates configuration files and tests to accommodate this feature. Modifies logger functions to handle custom time formats and improves test coverage to ensure correct functionality. --- README.md | 5 +- conf/examples/silver-kitchen-sink.conf | 1 + conf/examples/silver-log-stdout.conf | 3 +- lib/logging/logging.go | 44 +++++++-- lib/logging/logging_test.go | 49 ++++++++-- lib/logging/owner_unix_test.go | 22 ++++- service/config/config.go | 21 ++-- service/main.go | 19 ++-- service/main_logging_test.go | 98 +++++++++++++++++++ .../testdata/logging-defaultdateformat.conf | 14 +++ .../testdata/logging-with-microseconds.conf | 15 +++ 11 files changed, 255 insertions(+), 36 deletions(-) create mode 100644 service/main_logging_test.go create mode 100644 service/testdata/logging-defaultdateformat.conf create mode 100644 service/testdata/logging-with-microseconds.conf diff --git a/README.md b/README.md index a1caea9..b0dcbc0 100644 --- a/README.md +++ b/README.md @@ -83,6 +83,10 @@ 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. + "LogFileTimestampFormat": "2006-01-02 15:04:05.000000", + // File to store the current main service PID. "PidFile": "${ServiceRoot}/${ServiceName}.pid", @@ -434,4 +438,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..1643324 100644 --- a/lib/logging/logging.go +++ b/lib/logging/logging.go @@ -64,6 +64,16 @@ func init() { changeOwnerOfFileFunc = changeOwnerOfFile } +type logWriter struct { + io.Writer + timeformat string +} + +// custom Write to add timestamps with custom format +func (writer logWriter) Write(bytes []byte) (int, error) { + return fmt.Fprintf(writer.Writer, "%s %s", time.Now().Format(writer.timeformat), string(bytes)) +} + func (f *flusher) run(rf *rollingFile) { tick := time.Tick(f.interval) for { @@ -176,12 +186,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 +200,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 +229,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..afe32d0 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, "", "2006-01-02 15:04:05") defer func() { os.Remove(lname) }() msg := "TestStandardLogging" - logger.Printf(msg) + logger.Print(msg) CloseAllOpenFileLoggers() output, err := os.ReadFile(lname) @@ -25,8 +26,43 @@ 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 + re := regexp.MustCompile(`^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} [APM]{2} ` + msg) + 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 +70,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 15:04:05") 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. @@ -74,9 +110,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, "2006-01-02 15:04:05") defer func() { CloseAllOpenFileLoggers() os.Remove(lname) diff --git a/lib/logging/owner_unix_test.go b/lib/logging/owner_unix_test.go index fcfe66f..c3ea514 100644 --- a/lib/logging/owner_unix_test.go +++ b/lib/logging/owner_unix_test.go @@ -23,7 +23,27 @@ 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, "2006-01-02 15:04:05") + "os" + "testing" + "time" +) + +func TestLogIsOwnedByCorrectUser(t *testing.T) { + userName := "correct_user" + + functionCalled := false + // Mock the function + changeOwnerOfFileFunc = func(name string, owner string) error { + if owner == userName { + functionCalled = true + } + return nil + } + + lname := fmt.Sprintf("%s/test-standard-log-%d.log", os.TempDir(), time.Now().Unix()) + + logger := NewFileLogger(lname, userName, "2006-01-02 15:04:05") defer func() { os.Remove(lname) }() diff --git a/service/config/config.go b/service/config/config.go index b2273fe..3dfd510 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 { @@ -211,6 +212,10 @@ func (conf *Config) applyDefaults() { conf.EnvironmentVars = make(map[string]string) } + if conf.ServiceConfig.LogFileTimestampFormat == "" { + conf.ServiceConfig.LogFileTimestampFormat = "2006-01-02 15:04:05" + } + // Default graceful is 5 seconds for i := range conf.Services { if conf.Services[i].GracefulShutdownTimeoutSecs == 0 { 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..b69597e --- /dev/null +++ b/service/main_logging_test.go @@ -0,0 +1,98 @@ +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 timestamp without microseconds, got %q", line) + } + + reMicro := regexp.MustCompile(`^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{6} `) + if reMicro.MatchString(line) { + t.Fatalf("did not expect microsecond precision, 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" + } + ] +} From d80154bc6a2fc22f0568106dd75469022908ca33 Mon Sep 17 00:00:00 2001 From: Lars Pehrsson Date: Thu, 18 Sep 2025 08:48:42 +1000 Subject: [PATCH 2/6] Updated regex comment --- lib/logging/logging_test.go | 5 ++--- lib/logging/owner_unix_test.go | 20 -------------------- 2 files changed, 2 insertions(+), 23 deletions(-) diff --git a/lib/logging/logging_test.go b/lib/logging/logging_test.go index afe32d0..b36b881 100644 --- a/lib/logging/logging_test.go +++ b/lib/logging/logging_test.go @@ -27,7 +27,7 @@ func TestStandardLogging(t *testing.T) { } outstr := string(output) - // Expect format: YYYY/MM/DD HH:MM:SS + // 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) @@ -37,7 +37,6 @@ func TestStandardLogging(t *testing.T) { } } - func TestStandardTwelveHourLogging(t *testing.T) { lname := fmt.Sprintf("%s/test-standard-log-%d.log", os.TempDir(), time.Now().Unix()) @@ -56,7 +55,7 @@ func TestStandardTwelveHourLogging(t *testing.T) { } outstr := string(output) - // Expect format: YYYY/MM/DD HH:MM:SS + // 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} ` + msg) if !re.MatchString(outstr) { t.Errorf("expected timestamp prefix, got: %q", outstr) diff --git a/lib/logging/owner_unix_test.go b/lib/logging/owner_unix_test.go index c3ea514..955033c 100644 --- a/lib/logging/owner_unix_test.go +++ b/lib/logging/owner_unix_test.go @@ -9,26 +9,6 @@ import ( "time" ) -func TestLogIsOwnedByCorrectUser(t *testing.T) { - userName := "correct_user" - - functionCalled := false - // Mock the function - changeOwnerOfFileFunc = func(name string, owner string) error { - if owner == userName { - functionCalled = true - } - return nil - } - - lname := fmt.Sprintf("%s/test-standard-log-%d.log", os.TempDir(), time.Now().Unix()) - - logger := NewFileLogger(lname, userName, "2006-01-02 15:04:05") - "os" - "testing" - "time" -) - func TestLogIsOwnedByCorrectUser(t *testing.T) { userName := "correct_user" From 7678b29064967f4d869703444c77b5cca8127814 Mon Sep 17 00:00:00 2001 From: Lars Pehrsson Date: Thu, 18 Sep 2025 09:07:35 +1000 Subject: [PATCH 3/6] Removed default timestamp so we just rely on go log defaults --- service/config/config.go | 4 ---- service/main_logging_test.go | 9 ++------- 2 files changed, 2 insertions(+), 11 deletions(-) diff --git a/service/config/config.go b/service/config/config.go index 3dfd510..4a607de 100644 --- a/service/config/config.go +++ b/service/config/config.go @@ -212,10 +212,6 @@ func (conf *Config) applyDefaults() { conf.EnvironmentVars = make(map[string]string) } - if conf.ServiceConfig.LogFileTimestampFormat == "" { - conf.ServiceConfig.LogFileTimestampFormat = "2006-01-02 15:04:05" - } - // Default graceful is 5 seconds for i := range conf.Services { if conf.Services[i].GracefulShutdownTimeoutSecs == 0 { diff --git a/service/main_logging_test.go b/service/main_logging_test.go index b69597e..7ab33fd 100644 --- a/service/main_logging_test.go +++ b/service/main_logging_test.go @@ -30,14 +30,9 @@ func TestLogging_SampleConfigWithDefaultDateFormat(t *testing.T) { } line := string(data) - reDate := regexp.MustCompile(`^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2} `) + reDate := regexp.MustCompile(`^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} `) if !reDate.MatchString(line) { - t.Fatalf("expected timestamp without microseconds, got %q", line) - } - - reMicro := regexp.MustCompile(`^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{6} `) - if reMicro.MatchString(line) { - t.Fatalf("did not expect microsecond precision, got %q", line) + t.Fatalf("expected default date format without microseconds, got %q", line) } if !strings.Contains(line, testmessage) { From fd62ff5ff3247ccdfb64341036e5500f34898442 Mon Sep 17 00:00:00 2001 From: Lars Pehrsson Date: Thu, 18 Sep 2025 09:17:49 +1000 Subject: [PATCH 4/6] Standardizes timestamp formats in logging tests Revises logger initialization to use consistent timestamp formats across tests. Updates regex patterns to reflect the new formats. Ensures log message verification aligns with changed timestamp patterns. This aims to improve test clarity and reduce format-related errors. --- lib/logging/logging_test.go | 19 ++++++++++++------- lib/logging/owner_unix_test.go | 2 +- 2 files changed, 13 insertions(+), 8 deletions(-) diff --git a/lib/logging/logging_test.go b/lib/logging/logging_test.go index b36b881..960d90c 100644 --- a/lib/logging/logging_test.go +++ b/lib/logging/logging_test.go @@ -12,7 +12,7 @@ import ( func TestStandardLogging(t *testing.T) { lname := fmt.Sprintf("%s/test-standard-log-%d.log", os.TempDir(), time.Now().Unix()) - logger := NewFileLogger(lname, "", "2006-01-02 15:04:05") + logger := NewFileLogger(lname, "", "") defer func() { os.Remove(lname) }() @@ -28,7 +28,7 @@ func TestStandardLogging(t *testing.T) { 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} `) + 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) } @@ -56,7 +56,7 @@ func TestStandardTwelveHourLogging(t *testing.T) { 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} ` + msg) + 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) } @@ -69,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, "2006-01-02 15:04:05") + 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. @@ -94,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. } @@ -110,7 +115,7 @@ func TestRollingLog(t *testing.T) { func TestRollingLogFlush_IsFlushed(t *testing.T) { // Arrange lname := fmt.Sprintf("test-flushed-log-%d.log", time.Now().Unix()) - logger := NewFileLoggerWithMaxSize(lname, "", 10024, 5, "2006-01-02 15:04:05") + 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 955033c..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, "2006-01-02 15:04:05") + logger := NewFileLogger(lname, userName, "") defer func() { os.Remove(lname) }() From d2335c46351c64da7228e8290e40663a944f4acc Mon Sep 17 00:00:00 2001 From: Lars Pehrsson Date: Thu, 18 Sep 2025 11:46:13 +1000 Subject: [PATCH 5/6] Added link to go documentation --- README.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/README.md b/README.md index b0dcbc0..661a797 100644 --- a/README.md +++ b/README.md @@ -84,7 +84,8 @@ The configuration file is the heart of Silver. Here is a comprehensive example w "LogFileMaxBackupFiles": 5, // Custom format for log timestamps (e.g., "2006-01-02 15:04:05.000"). - // If set, this overrides the default timestamp format. + // 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. From 62af1b78e5f95b865fdc7bdf64e938e320094f2e Mon Sep 17 00:00:00 2001 From: Lars Pehrsson Date: Fri, 19 Sep 2025 10:51:02 +1000 Subject: [PATCH 6/6] Optimized new log writer with suggestions from Hiroshi --- lib/logging/logging.go | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/lib/logging/logging.go b/lib/logging/logging.go index 1643324..d06f92b 100644 --- a/lib/logging/logging.go +++ b/lib/logging/logging.go @@ -70,8 +70,14 @@ type logWriter struct { } // custom Write to add timestamps with custom format -func (writer logWriter) Write(bytes []byte) (int, error) { - return fmt.Fprintf(writer.Writer, "%s %s", time.Now().Format(writer.timeformat), string(bytes)) +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) {