diff --git a/Makefile b/Makefile index ae79409f..c933b6e3 100644 --- a/Makefile +++ b/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) \ diff --git a/pkg/gotenberg/logging.go b/pkg/gotenberg/logging.go index 37a39da1..7e8e63ab 100644 --- a/pkg/gotenberg/logging.go +++ b/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)) diff --git a/pkg/modules/logging/logging.go b/pkg/modules/logging/logging.go index 6f8ef456..dda41c4b 100644 --- a/pkg/modules/logging/logging.go +++ b/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) ) diff --git a/pkg/modules/logging/logging_test.go b/pkg/modules/logging/logging_test.go index 3212b770..b6d4fa8a 100644 --- a/pkg/modules/logging/logging_test.go +++ b/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) -)