Merge pull request #47 from PaperCutSoftware/feature/custom_logformat

Feature/custom logformat

Author: larspehrsson

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.
-

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": {

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": [
         {

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
 }

lib/logging/logging_test.go

@@ -3,6 +3,7 @@ package logging
 import (
 	"fmt"
 	"os"
+	"regexp"
 	"strings"
 	"testing"
 	"time"
@@ -11,30 +12,64 @@ 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)
 	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)
+	outstr := string(output)
+	// Expect format: YYYY-MM-DD HH:MM:SS <msg>
+	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] <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)
+	}
+	if !strings.Contains(outstr, msg) {
+		t.Errorf("Expected '%s', got '%s'", msg, outstr)
 	}
 }
 
 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)

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)
 	}()

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 {

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 {