feat(logging): add a new flag for preprending a prefix to each field in the logs (close #659)

Makefile

@@ -48,6 +48,7 @@ CHROMIUM_DISABLE_ROUTES=false
 LIBREOFFICE_DISABLES_ROUTES=false
 LOG_LEVEL=info
 LOG_FORMAT=auto
+LOG_FIELDS_PREFIX=
 PDFENGINES_ENGINES=
 PDFENGINES_DISABLE_ROUTES=false
 PROMETHEUS_NAMESPACE=gotenberg
@@ -94,6 +95,7 @@ run: ## Start a Gotenberg container
 	--libreoffice-disable-routes=$(LIBREOFFICE_DISABLES_ROUTES) \
 	--log-level=$(LOG_LEVEL) \
 	--log-format=$(LOG_FORMAT) \
+	--log-fields-prefix=$(LOG_FIELDS_PREFIX) \
 	--pdfengines-engines=$(PDFENGINES_ENGINES) \
 	--pdfengines-disable-routes=$(PDFENGINES_DISABLE_ROUTES) \
 	--prometheus-namespace=$(PROMETHEUS_NAMESPACE) \

pkg/gotenberg/logging.go

@@ -2,8 +2,8 @@ package gotenberg
 
 import "go.uber.org/zap"
 
-// LoggerProvider is a module interface which exposes a method for creating a
-// zap.Logger for other modules.
+// LoggerProvider is an interface for a module that supplies a method for
+// creating a zap.Logger instance for use by other modules.
 //
 //	func (m *YourModule) Provision(ctx *gotenberg.Context) error {
 //		provider, _ := ctx.Module(new(gotenberg.LoggerProvider))

pkg/modules/logging/logging.go

@@ -32,8 +32,9 @@ const (
 
 // Logging is a module which implements the gotenberg.LoggerProvider interface.
 type Logging struct {
-	level  string
-	format string
+	level        string
+	format       string
+	fieldsPrefix string
 }
 
 // Descriptor returns a Logging's module descriptor.
@@ -42,8 +43,9 @@ func (Logging) Descriptor() gotenberg.ModuleDescriptor {
 		ID: "logging",
 		FlagSet: func() *flag.FlagSet {
 			fs := flag.NewFlagSet("logging", flag.ExitOnError)
-			fs.String("log-level", infoLoggingLevel, fmt.Sprintf("Set the log level - %s, %s, %s, or %s", errorLoggingLevel, warnLoggingLevel, infoLoggingLevel, debugLoggingLevel))
-			fs.String("log-format", autoLoggingFormat, fmt.Sprintf("Set log format - %s, %s, or %s", autoLoggingFormat, jsonLoggingFormat, textLoggingFormat))
+			fs.String("log-level", infoLoggingLevel, fmt.Sprintf("Choose the level of logging detail. Options include %s, %s, %s, or %s", errorLoggingLevel, warnLoggingLevel, infoLoggingLevel, debugLoggingLevel))
+			fs.String("log-format", autoLoggingFormat, fmt.Sprintf("Specify the format of logging. Options include %s, %s, or %s", autoLoggingFormat, jsonLoggingFormat, textLoggingFormat))
+			fs.String("log-fields-prefix", "", "Prepend a specified prefix to each field in the logs")
 
 			return fs
 		}(),
@@ -57,6 +59,7 @@ func (log *Logging) Provision(ctx *gotenberg.Context) error {
 
 	log.level = flags.MustString("log-level")
 	log.format = flags.MustString("log-format")
+	log.fieldsPrefix = flags.MustString("log-fields-prefix")
 
 	return nil
 }
@@ -101,29 +104,64 @@ func (log Logging) Logger(mod gotenberg.Module) (*zap.Logger, error) {
 			return nil, fmt.Errorf("get log encoder: %w", err)
 		}
 
-		core := zapcore.NewCore(encoder, os.Stderr, lvl)
-		logger = zap.New(core)
-
-		// nolint
-		defer logger.Sync()
+		logger = zap.New(customCore{
+			Core:         zapcore.NewCore(encoder, os.Stderr, lvl),
+			fieldsPrefix: log.fieldsPrefix,
+		})
 	}
 
 	return logger.Named(mod.Descriptor().ID), nil
 }
 
-func newLogLevel(level string) (zapcore.Level, error) {
-	switch level {
-	case errorLoggingLevel:
-		return zap.ErrorLevel, nil
-	case warnLoggingLevel:
-		return zap.WarnLevel, nil
-	case infoLoggingLevel:
-		return zap.InfoLevel, nil
-	case debugLoggingLevel:
-		return zap.DebugLevel, nil
-	default:
-		return -2, fmt.Errorf("%s is not a recognized log level", level)
+// See https://github.com/gotenberg/gotenberg/issues/659.
+type customCore struct {
+	zapcore.Core
+	fieldsPrefix string
+}
+
+func (c customCore) With(fields []zapcore.Field) zapcore.Core {
+	if c.fieldsPrefix != "" {
+		for i := range fields {
+			fields[i].Key = c.fieldsPrefix + "_" + fields[i].Key
+		}
 	}
+
+	return customCore{
+		Core:         c.Core.With(fields),
+		fieldsPrefix: c.fieldsPrefix,
+	}
+}
+
+func (c customCore) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry {
+	// This is a copy from the zapcore.ioCore implementation. Indeed, by doing
+	// so, we are able to prefix the fields given to the logger methods like
+	// Debug, Info, Warn, Error, etc.
+	if c.Enabled(ent.Level) {
+		return ce.AddCore(ent, c)
+	}
+
+	return ce
+}
+
+func (c customCore) Write(entry zapcore.Entry, fields []zapcore.Field) error {
+	if c.fieldsPrefix != "" {
+		for i := range fields {
+			fields[i].Key = c.fieldsPrefix + "_" + fields[i].Key
+		}
+	}
+
+	return c.Core.Write(entry, fields)
+}
+
+func newLogLevel(level string) (zapcore.Level, error) {
+	lvl := zapcore.InvalidLevel
+
+	err := lvl.UnmarshalText([]byte(level))
+	if err != nil {
+		return lvl, fmt.Errorf("%q is not a recognized log level: %w", level, err)
+	}
+
+	return lvl, nil
 }
 
 func newLogEncoder(format string) (zapcore.Encoder, error) {
@@ -158,6 +196,7 @@ func newLogEncoder(format string) (zapcore.Encoder, error) {
 	}
 }
 
+// Singleton so that we instantiate our logger only once.
 var logger *zap.Logger = nil
 
 // Interface guards.
@@ -166,4 +205,5 @@ var (
 	_ gotenberg.Provisioner    = (*Logging)(nil)
 	_ gotenberg.Validator      = (*Logging)(nil)
 	_ gotenberg.LoggerProvider = (*Logging)(nil)
+	_ zapcore.Core             = (*customCore)(nil)
 )

pkg/modules/logging/logging_test.go

@@ -1,24 +1,18 @@
 package logging
 
 import (
+	"fmt"
 	"reflect"
 	"testing"
 
 	"github.com/gotenberg/gotenberg/v7/pkg/gotenberg"
+	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
+	"go.uber.org/zap/zaptest/observer"
 )
 
-type ProtoModule struct {
-	descriptor func() gotenberg.ModuleDescriptor
-}
-
-func (mod ProtoModule) Descriptor() gotenberg.ModuleDescriptor {
-	return mod.descriptor()
-}
-
 func TestLogging_Descriptor(t *testing.T) {
 	descriptor := Logging{}.Descriptor()
-
 	actual := reflect.TypeOf(descriptor.New())
 	expect := reflect.TypeOf(new(Logging))
 
@@ -28,155 +22,302 @@ func TestLogging_Descriptor(t *testing.T) {
 }
 
 func TestLogging_Provision(t *testing.T) {
-	logging := new(Logging)
-	fs := logging.Descriptor().FlagSet
+	for _, tc := range []struct {
+		scenario           string
+		level              string
+		format             string
+		fieldsPrefix       string
+		expectLevel        string
+		expectFormat       string
+		expectFieldsPrefix string
+	}{
+		{
+			scenario:           "default values",
+			expectLevel:        infoLoggingLevel,
+			expectFormat:       autoLoggingFormat,
+			expectFieldsPrefix: "",
+		},
+		{
+			scenario:           "explicit values",
+			level:              "debug",
+			format:             "json",
+			fieldsPrefix:       "gotenberg",
+			expectLevel:        debugLoggingLevel,
+			expectFormat:       jsonLoggingFormat,
+			expectFieldsPrefix: "gotenberg",
+		},
+		{
+			scenario:           "wrong values", // no validation at this point.
+			level:              "foo",
+			format:             "foo",
+			expectLevel:        "foo",
+			expectFormat:       "foo",
+			expectFieldsPrefix: "",
+		},
+	} {
+		var flags []string
 
-	err := fs.Parse([]string{""})
-	if err != nil {
-		t.Fatalf("expected no error but got: %v", err)
-	}
+		if tc.level != "" {
+			flags = append(flags, "--log-level", tc.level)
+		}
 
-	ctx := gotenberg.NewContext(gotenberg.ParsedFlags{FlagSet: fs}, nil)
+		if tc.format != "" {
+			flags = append(flags, "--log-format", tc.format)
+		}
 
-	err = logging.Provision(ctx)
-	if err != nil {
-		t.Errorf("expected no error but got: %v", err)
+		if tc.fieldsPrefix != "" {
+			flags = append(flags, "--log-fields-prefix", tc.fieldsPrefix)
+		}
+
+		logging := new(Logging)
+		fs := logging.Descriptor().FlagSet
+
+		err := fs.Parse(flags)
+		if err != nil {
+			t.Fatalf("%s: expected no error but got: %v", tc.scenario, err)
+		}
+
+		ctx := gotenberg.NewContext(gotenberg.ParsedFlags{FlagSet: fs}, nil)
+
+		err = logging.Provision(ctx)
+		if err != nil {
+			t.Fatalf("%s: expected no error but got: %v", tc.scenario, err)
+		}
+
+		if logging.level != tc.expectLevel {
+			t.Errorf("%s: expected '%s' but got '%s'", tc.scenario, tc.expectLevel, logging.level)
+		}
+
+		if logging.format != tc.expectFormat {
+			t.Errorf("%s: expected '%s' but got '%s'", tc.scenario, tc.expectFormat, logging.format)
+		}
+
+		if logging.fieldsPrefix != tc.expectFieldsPrefix {
+			t.Errorf("%s: expected '%s' but got '%s'", tc.scenario, tc.expectFieldsPrefix, logging.fieldsPrefix)
+		}
 	}
 }
 
 func TestLogging_Validate(t *testing.T) {
-	for i, tc := range []struct {
-		level, format string
-		expectErr     bool
+	for _, tc := range []struct {
+		scenario  string
+		level     string
+		format    string
+		expectErr bool
 	}{
 		{
+			scenario:  "invalid level",
 			level:     "foo",
 			expectErr: true,
 		},
 		{
+			scenario:  "invalid format",
 			level:     debugLoggingLevel,
 			format:    "foo",
 			expectErr: true,
 		},
 		{
-			level:  debugLoggingLevel,
-			format: autoLoggingFormat,
+			scenario: "valid level and format",
+			level:    debugLoggingLevel,
+			format:   autoLoggingFormat,
 		},
 	} {
-		mod := new(Logging)
-		mod.level = tc.level
-		mod.format = tc.format
+		logging := new(Logging)
+		logging.level = tc.level
+		logging.format = tc.format
 
-		err := mod.Validate()
+		err := logging.Validate()
 
 		if tc.expectErr && err == nil {
-			t.Errorf("test %d: expected error but got: %v", i, err)
+			t.Errorf("%s: expected error but got: %v", tc.scenario, err)
 		}
 
 		if !tc.expectErr && err != nil {
-			t.Errorf("test %d: expected no error but got: %v", i, err)
+			t.Errorf("%s: expected no error but got: %v", tc.scenario, err)
 		}
 	}
 }
 
 func TestLogging_Logger(t *testing.T) {
-	for i, tc := range []struct {
-		level, format string
-		expectErr     bool
+	for _, tc := range []struct {
+		scenario     string
+		level        string
+		format       string
+		fieldsPrefix string
+		expectErr    bool
 	}{
 		{
+			scenario:  "invalid level",
 			level:     "foo",
 			expectErr: true,
 		},
 		{
+			scenario:  "invalid format",
 			level:     debugLoggingLevel,
 			format:    "foo",
 			expectErr: true,
 		},
 		{
-			level:  debugLoggingLevel,
-			format: autoLoggingFormat,
+			scenario: "valid level and format",
+			level:    debugLoggingLevel,
+			format:   autoLoggingFormat,
 		},
 	} {
-		mod := new(Logging)
-		mod.level = tc.level
-		mod.format = tc.format
+		logging := new(Logging)
+		logging.level = tc.level
+		logging.format = tc.format
+		logging.fieldsPrefix = tc.fieldsPrefix
 
-		_, err := mod.Logger(ProtoModule{
-			descriptor: func() gotenberg.ModuleDescriptor {
-				return gotenberg.ModuleDescriptor{ID: "foo", New: nil}
+		_, err := logging.Logger(gotenberg.ModuleMock{
+			DescriptorMock: func() gotenberg.ModuleDescriptor {
+				return gotenberg.ModuleDescriptor{ID: "mock", New: nil}
 			},
 		})
 
 		if tc.expectErr && err == nil {
-			t.Errorf("test %d: expected error but got: %v", i, err)
+			t.Errorf("%s: expected error but got: %v", tc.scenario, err)
 		}
 
 		if !tc.expectErr && err != nil {
-			t.Errorf("test %d: expected no error but got: %v", i, err)
+			t.Errorf("%s: expected no error but got: %v", tc.scenario, err)
 		}
 	}
 }
 
-func TestNewLogLevel(t *testing.T) {
-	for i, tc := range []struct {
+func TestCustomCore(t *testing.T) {
+	for _, tc := range []struct {
+		scenario     string
+		level        zapcore.Level
+		fieldsPrefix string
+		expectEntry  bool
+	}{
+		{
+			scenario:     "level enabled",
+			level:        zapcore.DebugLevel,
+			fieldsPrefix: "gotenberg",
+			expectEntry:  true,
+		},
+		{
+			scenario:    "no fields prefix",
+			level:       zapcore.DebugLevel,
+			expectEntry: true,
+		},
+		{
+			scenario: "level disabled",
+			level:    zapcore.ErrorLevel,
+		},
+	} {
+		core, obsvr := observer.New(tc.level)
+		lgr := zap.New(customCore{
+			Core:         core,
+			fieldsPrefix: tc.fieldsPrefix,
+		}).With(zap.String("a_field", "a value"))
+
+		lgr.Debug("a debug message", zap.String("another_field", "another value"))
+
+		entries := obsvr.TakeAll()
+
+		if tc.expectEntry && len(entries) == 0 {
+			t.Fatalf("%s: expected an entry", tc.scenario)
+		}
+
+		if !tc.expectEntry && len(entries) != 0 {
+			t.Fatalf("%s: expected no entry", tc.scenario)
+		}
+
+		var prefix string
+		if tc.fieldsPrefix != "" {
+			prefix = tc.fieldsPrefix + "_"
+		}
+
+		for _, entry := range entries {
+			fields := entry.Context
+
+			if len(fields) != 2 {
+				t.Fatalf("expected 2 fields but got %d", len(fields))
+			}
+
+			if fields[0].Key != fmt.Sprintf("%sa_field", prefix) {
+				t.Errorf("expected 'gotenberg_a_field' but got '%s'", fields[0].Key)
+			}
+
+			if fields[1].Key != fmt.Sprintf("%sanother_field", prefix) {
+				t.Errorf("expected 'gotenberg_another_field' but got '%s'", fields[1].Key)
+			}
+		}
+	}
+}
+
+func Test_newLogLevel(t *testing.T) {
+	for _, tc := range []struct {
+		scenario       string
 		level          string
 		expectZapLevel zapcore.Level
 		expectErr      bool
 	}{
 		{
+			scenario:       "error level",
 			level:          errorLoggingLevel,
 			expectZapLevel: zapcore.ErrorLevel,
 		},
 		{
+			scenario:       "warning level",
 			level:          warnLoggingLevel,
 			expectZapLevel: zapcore.WarnLevel,
 		},
 		{
+			scenario:       "info level",
 			level:          infoLoggingLevel,
 			expectZapLevel: zapcore.InfoLevel,
 		},
 		{
+			scenario:       "debug level",
 			level:          debugLoggingLevel,
 			expectZapLevel: zapcore.DebugLevel,
 		},
 		{
+			scenario:       "invalid level",
 			level:          "foo",
-			expectZapLevel: -2,
+			expectZapLevel: zapcore.InvalidLevel,
 			expectErr:      true,
 		},
 	} {
 		actual, err := newLogLevel(tc.level)
 
 		if tc.expectErr && err == nil {
-			t.Errorf("test %d: expected error but got: %v", i, err)
+			t.Errorf("%s: expected error but got: %v", tc.scenario, err)
 		}
 
 		if !tc.expectErr && err != nil {
-			t.Errorf("test %d: expected no error but got: %v", i, err)
+			t.Errorf("%s: expected no error but got: %v", tc.scenario, err)
 		}
 
 		if tc.expectZapLevel != actual {
-			t.Errorf("test %d: expected %d level but got %d", i, tc.expectZapLevel, actual)
+			t.Errorf("%s: expected %d level but got %d", tc.scenario, tc.expectZapLevel, actual)
 		}
 	}
 }
 
-func TestNewLogEncoder(t *testing.T) {
-	for i, tc := range []struct {
+func Test_newLogEncoder(t *testing.T) {
+	for _, tc := range []struct {
+		scenario  string
 		format    string
 		expectErr bool
 	}{
 		{
-			format: autoLoggingFormat,
+			scenario: "auto format",
+			format:   autoLoggingFormat,
 		},
 		{
-			format: textLoggingFormat,
+			scenario: "text format",
+			format:   textLoggingFormat,
 		},
 		{
-			format: jsonLoggingFormat,
+			scenario: "json format",
+			format:   jsonLoggingFormat,
 		},
 		{
+			scenario:  "invalid format",
 			format:    "foo",
 			expectErr: true,
 		},
@@ -184,16 +325,11 @@ func TestNewLogEncoder(t *testing.T) {
 		_, err := newLogEncoder(tc.format)
 
 		if tc.expectErr && err == nil {
-			t.Errorf("test %d: expected error but got: %v", i, err)
+			t.Errorf("%s: expected error but got: %v", tc.scenario, err)
 		}
 
 		if !tc.expectErr && err != nil {
-			t.Errorf("test %d: expected no error but got: %v", i, err)
+			t.Errorf("%s: expected no error but got: %v", tc.scenario, err)
 		}
 	}
 }
-
-// Interface guards.
-var (
-	_ gotenberg.Module = (*ProtoModule)(nil)
-)