diff --git a/cmd/internal/serverutil/serverutil.go b/cmd/internal/serverutil/serverutil.go index bafdbb4..6708dc9 100644 --- a/cmd/internal/serverutil/serverutil.go +++ b/cmd/internal/serverutil/serverutil.go @@ -118,7 +118,7 @@ func (m *Main) Run(ctx context.Context) error { // nolint: funlen srv, err := m.newGRPCServer() if err != nil { - logger.Fatalf("Error creating gRPC server: %v", err) + logger.Fatal("Error creating gRPC server", log.WithError(err)) } defer srv.GracefulStop() @@ -138,7 +138,7 @@ func (m *Main) Run(ctx context.Context) error { // nolint: funlen http.HandleFunc("/healthz", m.healthz) go func() { - logger.Infof("HTTP server starting on %v", endpoint) + logger.Info("HTTP server starting", log.WithAddress(endpoint)) // Let http.ListenAndServeTLS handle the error case when only one of the flags is set. if m.TLSCertFile != "" || m.TLSKeyFile != "" { @@ -148,12 +148,12 @@ func (m *Main) Run(ctx context.Context) error { // nolint: funlen } if err != nil { - logger.Errorf("HTTP server stopped: %v", err) + logger.Error("HTTP server stopped", log.WithError(err)) } }() } - logger.Infof("RPC server starting on %v", m.RPCEndpoint) + logger.Info("RPC server starting", log.WithServiceEndpoint(m.RPCEndpoint)) lis, err := net.Listen("tcp", m.RPCEndpoint) if err != nil { @@ -164,7 +164,7 @@ func (m *Main) Run(ctx context.Context) error { // nolint: funlen if m.TreeGCEnabled { go func() { - logger.Infof("Deleted tree GC started") + logger.Info("Deleted tree GC started") gc := admin.NewDeletedTreeGC( m.Registry.AdminStorage, @@ -176,10 +176,10 @@ func (m *Main) Run(ctx context.Context) error { // nolint: funlen } if err := srv.Serve(lis); err != nil { - logger.Errorf("RPC server terminated: %v", err) + logger.Error("RPC server terminated", log.WithError(err)) } - logger.Infof("Stopping server, about to exit") + logger.Info("Stopping server, about to exit") // Give things a few seconds to tidy up time.Sleep(time.Second * 5) // nolint: gomnd @@ -227,23 +227,23 @@ func AnnounceSelf(ctx context.Context, client *clientv3.Client, etcdService, end // Get a lease so our entry self-destructs. leaseRsp, err := client.Grant(ctx, 30) if err != nil { - logger.Fatalf("Failed to get lease from etcd: %v", err) + logger.Fatal("Failed to get lease from etcd", log.WithError(err)) } client.KeepAlive(ctx, leaseRsp.ID) // nolint: errcheck, gosec em, err := endpoints.NewManager(client, etcdService) if err != nil { - logger.Fatalf("Failed to create etcd manager: %v", err) + logger.Fatal("Failed to create etcd manager", log.WithError(err)) } fullEndpoint := fmt.Sprintf("%s/%s", etcdService, endpoint) em.AddEndpoint(ctx, fullEndpoint, endpoints.Endpoint{Addr: endpoint}) // nolint: errcheck, gosec - logger.Infof("Announcing our presence in %v", etcdService) + logger.Info("Announcing our presence", log.WithServiceEndpoint(etcdService)) return func() { // Use a background context because the original context may have been cancelled. - logger.Infof("Removing our presence in %v", etcdService) + logger.Info("Removing our presence", log.WithServiceEndpoint(etcdService)) ctx := context.Background() em.DeleteEndpoint(ctx, fullEndpoint) // nolint: errcheck, gosec diff --git a/cmd/log_server/main.go b/cmd/log_server/main.go index 3ff92db..3b8485b 100644 --- a/cmd/log_server/main.go +++ b/cmd/log_server/main.go @@ -63,13 +63,13 @@ func main() { flag.Parse() if err := storage.RegisterProvider("mem", memory.NewMemoryStorageProvider); err != nil { - logger.Errorf(err.Error()) + logger.Error("Error registering memory storage provider", log.WithError(err)) } postgres.PGConnStr = *pgConnStr if err := storage.RegisterProvider("postgres", postgres.NewPGProvider); err != nil { - logger.Errorf(err.Error()) + logger.Error("Error registering PostGreSQL provider", log.WithError(err)) } startCMD := startcmd.CMD{ @@ -94,6 +94,6 @@ func main() { } if err := startCMD.Start(); err != nil { - logger.Fatalf("failed to start log server: %v", err) + logger.Fatal("Failed to start log server", log.WithError(err)) } } diff --git a/cmd/log_signer/main.go b/cmd/log_signer/main.go index a0d015f..4d81ea2 100644 --- a/cmd/log_signer/main.go +++ b/cmd/log_signer/main.go @@ -22,7 +22,7 @@ import ( "github.com/google/trillian/storage" "github.com/trustbloc/vct/cmd/log_signer/startcmd" - logging "github.com/trustbloc/vct/internal/pkg/log" + logs "github.com/trustbloc/vct/internal/pkg/log" "github.com/trustbloc/vct/pkg/storage/memory" "github.com/trustbloc/vct/pkg/storage/postgres" ) @@ -65,19 +65,19 @@ var ( pgConnStr = flag.String("pg_conn_str", "user=postgres dbname=test sslmode=disable", "Connection string for Postgres database") ) -var logger = logging.New("log-signer") +var logger = logs.New("log-signer") func main() { flag.Parse() if err := storage.RegisterProvider("mem", memory.NewMemoryStorageProvider); err != nil { - logger.Errorf(err.Error()) + logger.Error("Error registering memory storage provider", logs.WithError(err)) } postgres.PGConnStr = *pgConnStr if err := storage.RegisterProvider("postgres", postgres.NewPGProvider); err != nil { - logger.Errorf(err.Error()) + logger.Error("Error registering PostGreSQL storage provider", logs.WithError(err)) } startCMD := startcmd.CMD{ @@ -104,6 +104,6 @@ func main() { } if err := startCMD.Start(); err != nil { - logger.Fatalf("failed to start log signer: %v", err) + logger.Fatal("failed to start log signer", logs.WithError(err)) } } diff --git a/cmd/vct/main.go b/cmd/vct/main.go index 9aae9e3..c3d7be8 100644 --- a/cmd/vct/main.go +++ b/cmd/vct/main.go @@ -41,12 +41,12 @@ func main() { startCmd, err := startcmd.Cmd(&startcmd.HTTPServer{}) if err != nil { - logger.Fatalf(err.Error()) + logger.Fatal("Cannot start server", log.WithError(err)) } rootCmd.AddCommand(startCmd) if err := rootCmd.Execute(); err != nil { - logger.Fatalf("failed to run vct: %v", err) + logger.Fatal("Failed to run VCT", log.WithError(err)) } } diff --git a/cmd/vct/startcmd/start.go b/cmd/vct/startcmd/start.go index 65c0ff1..dd7e1c5 100644 --- a/cmd/vct/startcmd/start.go +++ b/cmd/vct/startcmd/start.go @@ -482,13 +482,13 @@ func createStartCMD(server server) *cobra.Command { //nolint: funlen,gocognit,go if starTrillian { //nolint: nestif if err := trillianstorage.RegisterProvider("mem", memory.NewMemoryStorageProvider); err != nil { - logger.Errorf(err.Error()) + logger.Error("Error registering memory storage provider", log.WithError(err)) } postgres.PGConnStr = trillianDBConnStr if err := trillianstorage.RegisterProvider("postgres", postgres.NewPGProvider); err != nil { - logger.Errorf(err.Error()) + logger.Error("Error registering PostGreSQL storage provider", log.WithError(err)) } go func() { @@ -717,7 +717,7 @@ func startAgent(parameters *agentParameters) error { //nolint:funlen,gocyclo,cyc defer func() { if err = store.Close(); err != nil { - logger.Errorf("store close: %v", err) + logger.Error("Close store error", log.WithError(err)) } }() @@ -861,7 +861,7 @@ func startAgent(parameters *agentParameters) error { //nolint:funlen,gocyclo,cyc go startMetrics(parameters, metricsRouter) - logger.Infof("Starting vct on host [%s]", parameters.host) + logger.Info("Starting VCT", log.WithAddress(parameters.host)) return parameters.server.ListenAndServe( // nolint: wrapcheck parameters.host, @@ -874,7 +874,8 @@ func startAgent(parameters *agentParameters) error { //nolint:funlen,gocyclo,cyc func startMetrics(parameters *agentParameters, route *mux.Router) { err := parameters.server.ListenAndServe(parameters.metricsHost, route, "", "") if err != nil { - logger.Fatalf("%v", err) + logger.Fatal("Error starting metrics service", + log.WithAddress(parameters.metricsHost), log.WithError(err)) } } @@ -914,7 +915,8 @@ func createTreeAndInit(conn *grpc.ClientConn, cfg storage.Store, alias string, t return err // nolint: wrapcheck }, backoff.WithMaxRetries(backoff.NewConstantBackOff(time.Second), timeout), func(err error, duration time.Duration) { - logger.Warnf("create tree failed, will sleep for %v before trying again: %v", duration, err) + logger.Warn("Create tree failed, will sleep a while before trying again", + log.WithBackoff(duration), log.WithError(err)) }) if err != nil { @@ -1064,7 +1066,8 @@ func createStoreProvider(dbURL, prefix string, timeout uint64) (storeProvider, e backoff.NewConstantBackOff(time.Second), timeout, ), func(retryErr error, t time.Duration) { - logger.Warnf("failed to connect to storage, will sleep for %s before trying again : %v", t, retryErr) + logger.Warn("Failed to connect to storage, will sleep a while before trying again", + log.WithBackoff(t), log.WithError(retryErr)) }) } diff --git a/internal/pkg/log/common.go b/internal/pkg/log/common.go new file mode 100644 index 0000000..eee9237 --- /dev/null +++ b/internal/pkg/log/common.go @@ -0,0 +1,14 @@ +/* +Copyright SecureKey Technologies Inc. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package log + +import "go.uber.org/zap" + +// WriteResponseBodyError outputs a 'write response body' error log to the given logger. +func WriteResponseBodyError(log *Log, err error) { + log.WithOptions(zap.AddCallerSkip(1)).Error("Error writing response body", WithError(err)) +} diff --git a/internal/pkg/log/common_test.go b/internal/pkg/log/common_test.go new file mode 100644 index 0000000..5140fbd --- /dev/null +++ b/internal/pkg/log/common_test.go @@ -0,0 +1,34 @@ +/* +Copyright SecureKey Technologies Inc. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package log + +import ( + "errors" + "testing" + + "github.com/stretchr/testify/require" +) + +func TestCommonLogs(t *testing.T) { + const module = "test_module" + + t.Run("WriteResponseBodyError", func(t *testing.T) { + stdErr := newMockWriter() + + logger := New(module, + WithStdErr(stdErr), + WithFields(WithServiceName("myservice")), + ) + + WriteResponseBodyError(logger, errors.New("response body error")) + + require.Contains(t, stdErr.Buffer.String(), `Error writing response body`) + require.Contains(t, stdErr.Buffer.String(), `"service": "myservice"`) + require.Contains(t, stdErr.Buffer.String(), `"error": "response body error"`) + require.Contains(t, stdErr.Buffer.String(), "log/common_test.go") + }) +} diff --git a/internal/pkg/log/fields.go b/internal/pkg/log/fields.go new file mode 100644 index 0000000..51922a7 --- /dev/null +++ b/internal/pkg/log/fields.go @@ -0,0 +1,117 @@ +/* +Copyright SecureKey Technologies Inc. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package log + +import ( + "time" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// Log Fields. +const ( + FieldServiceName = "service" + FieldSize = "size" + FieldAddress = "address" + FieldBackoff = "backoff" + FieldServiceEndpoint = "serviceEndpoint" + FieldTreeID = "treeID" + FieldLeaf = "leaf" + FieldStore = "store" + FieldCommand = "command" + FieldVerifiableCredential = "vc" + FieldSignature = "signature" + FieldTimestamp = "timestamp" + FieldPublicKey = "publicKey" +) + +// WithError sets the error field. +func WithError(err error) zap.Field { + return zap.Error(err) +} + +// WithServiceName sets the service field. +func WithServiceName(value string) zap.Field { + return zap.String(FieldServiceName, value) +} + +// WithSize sets the size field. +func WithSize(value int) zap.Field { + return zap.Int(FieldSize, value) +} + +// WithAddress sets the address field. +func WithAddress(value string) zap.Field { + return zap.String(FieldAddress, value) +} + +// WithBackoff sets the backoff field. +func WithBackoff(value time.Duration) zap.Field { + return zap.Duration(FieldBackoff, value) +} + +// WithServiceEndpoint sets the service-endpoint field. +func WithServiceEndpoint(value string) zap.Field { + return zap.String(FieldServiceEndpoint, value) +} + +// WithTreeID sets the service-endpoint field. +func WithTreeID(value int64) zap.Field { + return zap.Int64(FieldTreeID, value) +} + +// WithLeaf sets the leaf field. +func WithLeaf(value interface{}) zap.Field { + return zap.Inline(NewObjectMarshaller(FieldLeaf, value)) +} + +// WithStore sets the store field. +func WithStore(value string) zap.Field { + return zap.String(FieldStore, value) +} + +// WithCommand sets the command field. +func WithCommand(value string) zap.Field { + return zap.String(FieldCommand, value) +} + +// WithVerifiableCredential sets the vc field. +func WithVerifiableCredential(value []byte) zap.Field { + return zap.String(FieldVerifiableCredential, string(value)) +} + +// WithSignature sets the signature field. +func WithSignature(value []byte) zap.Field { + return zap.ByteString(FieldSignature, value) +} + +// WithTimestamp sets the timestamp field. +func WithTimestamp(value uint64) zap.Field { + return zap.Uint64(FieldTimestamp, value) +} + +// WithPublicKey sets the timestamp field. +func WithPublicKey(value interface{}) zap.Field { + return zap.Inline(NewObjectMarshaller(FieldPublicKey, value)) +} + +// ObjectMarshaller uses reflection to marshal an object's fields. +type ObjectMarshaller struct { + key string + obj interface{} +} + +// NewObjectMarshaller returns a new ObjectMarshaller. +func NewObjectMarshaller(key string, obj interface{}) *ObjectMarshaller { + return &ObjectMarshaller{key: key, obj: obj} +} + +// MarshalLogObject marshals the object's fields. +func (m *ObjectMarshaller) MarshalLogObject(e zapcore.ObjectEncoder) error { + return e.AddReflected(m.key, m.obj) +} diff --git a/internal/pkg/log/fields_test.go b/internal/pkg/log/fields_test.go new file mode 100644 index 0000000..f9f3ed1 --- /dev/null +++ b/internal/pkg/log/fields_test.go @@ -0,0 +1,138 @@ +/* +Copyright SecureKey Technologies Inc. All Rights Reserved. + +SPDX-License-Identifier: Apache-2.0 +*/ + +package log + +import ( + "encoding/json" + "errors" + "net/url" + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +func TestStandardFields(t *testing.T) { + const module = "test_module" + + u1 := parseURL(t, "https://example1.com") + + t.Run("console error", func(t *testing.T) { + stdErr := newMockWriter() + + logger := New(module, + WithStdErr(stdErr), + WithFields(WithServiceName("myservice")), + ) + + logger.Error("Sample error", WithError(errors.New("some error"))) + + require.Contains(t, stdErr.Buffer.String(), `Sample error {"service": "myservice", "error": "some error"}`) + }) + + t.Run("json error", func(t *testing.T) { + stdErr := newMockWriter() + + logger := New(module, + WithStdErr(stdErr), WithEncoding(JSON), + WithFields(WithServiceName("myservice")), + ) + + logger.Error("Sample error", WithError(errors.New("some error"))) + + l := unmarshalLogData(t, stdErr.Bytes()) + + require.Equal(t, "myservice", l.Service) + require.Equal(t, "test_module", l.Logger) + require.Equal(t, "Sample error", l.Msg) + require.Contains(t, l.Caller, "log/fields_test.go") + require.Equal(t, "some error", l.Error) + require.Equal(t, "error", l.Level) + }) + + t.Run("json fields", func(t *testing.T) { + leaf := &mockObject{Field1: "leaf1", Field2: 32123} + pubKey := &mockObject{Field1: "key1", Field2: 32432} + + stdOut := newMockWriter() + + logger := New(module, WithStdOut(stdOut), WithEncoding(JSON)) + + logger.Info("Some message", + WithServiceName("service1"), WithSize(1234), WithAddress(u1.String()), + WithBackoff(time.Minute), WithServiceEndpoint(u1.String()), WithTreeID(1234), + WithLeaf(leaf), WithStore("store1"), WithCommand("doit"), + WithVerifiableCredential([]byte(`"id":"vc1"`)), WithSignature([]byte("my signature")), + WithTimestamp(321232), WithPublicKey(pubKey), + ) + + t.Logf(stdOut.String()) + l := unmarshalLogData(t, stdOut.Bytes()) + + require.Equal(t, `Some message`, l.Msg) + require.Equal(t, `service1`, l.Service) + require.Equal(t, 1234, l.Size) + require.Equal(t, u1.String(), l.Address) + require.Equal(t, "1m0s", l.Backoff) + require.Equal(t, u1.String(), l.ServiceEndpoint) + require.Equal(t, 1234, l.TreeID) + require.Equal(t, leaf, l.Leaf) + require.Equal(t, "store1", l.Store) + require.Equal(t, "doit", l.Command) + require.Equal(t, `"id":"vc1"`, l.VerifiableCredential) + require.Equal(t, "my signature", l.Signature) + require.Equal(t, 321232, l.Timestamp) + require.Equal(t, pubKey, l.PublicKey) + }) +} + +type mockObject struct { + Field1 string + Field2 int +} + +type logData struct { + Level string `json:"level"` + Time string `json:"time"` + Logger string `json:"logger"` + Caller string `json:"caller"` + Msg string `json:"msg"` + Error string `json:"error"` + + Service string `json:"service"` + Size int `json:"size"` + Address string `json:"address"` + Backoff string `json:"backoff"` + ServiceEndpoint string `json:"serviceEndpoint"` + TreeID int `json:"treeID"` + Leaf *mockObject `json:"leaf"` + Store string `json:"store"` + Command string `json:"command"` + VerifiableCredential string `json:"vc"` + Signature string `json:"signature"` + Timestamp int `json:"timestamp"` + PublicKey *mockObject `json:"publicKey"` +} + +func unmarshalLogData(t *testing.T, b []byte) *logData { + t.Helper() + + l := &logData{} + + require.NoError(t, json.Unmarshal(b, l)) + + return l +} + +func parseURL(t *testing.T, raw string) *url.URL { + t.Helper() + + u, err := url.Parse(raw) + require.NoError(t, err) + + return u +} diff --git a/internal/pkg/log/logger.go b/internal/pkg/log/logger.go index bbe8612..d03589f 100644 --- a/internal/pkg/log/logger.go +++ b/internal/pkg/log/logger.go @@ -17,6 +17,19 @@ import ( "go.uber.org/zap/zapcore" ) +const ( + timestampKey = "time" + levelKey = "level" + moduleKey = "logger" + callerKey = "caller" + messageKey = "msg" + stacktraceKey = "stacktrace" +) + +// DefaultEncoding sets the default logger encoding. +// It may be overridden at build time using the -ldflags option. +var DefaultEncoding = Console //nolint:gochecknoglobals + // Level defines a log level for logging messages. type Level int @@ -69,125 +82,75 @@ const ( PANIC = Level(zapcore.PanicLevel) FATAL = Level(zapcore.FatalLevel) - minLogLevel = DEBUG -) - -const ( - defaultLevel = INFO - defaultModuleName = "" - callerSkip = 1 + minLogLevel = DEBUG + defaultLevel = INFO ) var levels = newModuleLevels() //nolint:gochecknoglobals -// Log is an implementation of Logger interface. -type Log struct { - instance *zap.SugaredLogger - module string +type options struct { + encoding Encoding stdOut zapcore.WriteSyncer stdErr zapcore.WriteSyncer + fields []zap.Field } +// Encoding defines the log encoding. +type Encoding = string + +// Log encodings. +const ( + Console Encoding = "console" + JSON Encoding = "json" +) + +const defaultModuleName = "" + // Option is a logger option. -type Option func(l *Log) +type Option func(o *options) // WithStdOut sets the output for logs of type DEBUG, INFO, and WARN. func WithStdOut(stdOut zapcore.WriteSyncer) Option { - return func(l *Log) { - l.stdOut = stdOut + return func(o *options) { + o.stdOut = stdOut } } // WithStdErr sets the output for logs of type ERROR, PANIC, and FATAL. func WithStdErr(stdErr zapcore.WriteSyncer) Option { - return func(l *Log) { - l.stdErr = stdErr + return func(o *options) { + o.stdErr = stdErr } } -// New creates and returns a Logger implementation based on given module name. -// note: the underlying logger instance is lazy initialized on first use. -// To use your own logger implementation provide logger provider in 'Initialize()' before logging any line. -// If 'Initialize()' is not called before logging any line then default logging implementation will be used. -func New(module string, opts ...Option) *Log { - l := &Log{ - module: module, - stdOut: os.Stdout, - stdErr: os.Stderr, +// WithFields sets the fields that will be output with every log. +func WithFields(fields ...zap.Field) Option { + return func(o *options) { + o.fields = fields } - - for _, opt := range opts { - opt(l) - } - - l.initialize() - - return l -} - -func (l *Log) initialize() { - encoder := zapcore.NewConsoleEncoder(zapcore.EncoderConfig{ - TimeKey: "ts", - LevelKey: "level", - NameKey: "logger", - CallerKey: "caller", - FunctionKey: zapcore.OmitKey, - MessageKey: "msg", - StacktraceKey: "stacktrace", - LineEnding: zapcore.DefaultLineEnding, - EncodeLevel: zapcore.CapitalLevelEncoder, - EncodeTime: zapcore.ISO8601TimeEncoder, - EncodeDuration: zapcore.StringDurationEncoder, - EncodeCaller: zapcore.ShortCallerEncoder, - EncodeName: func(moduleName string, encoder zapcore.PrimitiveArrayEncoder) { - encoder.AppendString(fmt.Sprintf("[%s]", moduleName)) - }, - }) - - core := zapcore.NewTee( - zapcore.NewCore(encoder, zapcore.Lock(l.stdErr), - zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { - return lvl >= zapcore.ErrorLevel && levels.isEnabled(l.module, Level(lvl)) - }), - ), - zapcore.NewCore(encoder, zapcore.Lock(l.stdOut), - zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { - return lvl < zapcore.ErrorLevel && levels.isEnabled(l.module, Level(lvl)) - }), - ), - ) - - l.instance = zap.New(core, zap.AddCaller(), zap.AddCallerSkip(callerSkip)).Named(l.module).Sugar() -} - -// Fatalf log a templated message, then calls os.Exit. -func (l *Log) Fatalf(msg string, args ...interface{}) { - l.instance.Fatalf(msg, args...) -} - -// Panicf log a templated message, then panics. -func (l *Log) Panicf(msg string, args ...interface{}) { - l.instance.Panicf(msg, args...) } -// Debugf logs a templated message. -func (l *Log) Debugf(msg string, args ...interface{}) { - l.instance.Debugf(msg, args...) +// WithEncoding sets the output encoding (console or json). +func WithEncoding(encoding Encoding) Option { + return func(o *options) { + o.encoding = encoding + } } -// Infof logs a templated message. -func (l *Log) Infof(msg string, args ...interface{}) { - l.instance.Infof(msg, args...) +// Log uses the Zap Logger to log messages in a structured way. +type Log struct { + *zap.Logger + module string } -// Warnf logs a templated message. -func (l *Log) Warnf(msg string, args ...interface{}) { - l.instance.Warnf(msg, args...) -} +// New creates a structured Logger implementation based on given module name. +func New(module string, opts ...Option) *Log { + options := getOptions(opts) -// Errorf logs a templated message. -func (l *Log) Errorf(msg string, args ...interface{}) { - l.instance.Errorf(msg, args...) + return &Log{ + Logger: newZap(module, options.encoding, options.stdOut, options.stdErr).With(options.fields...), + module: module, + } } // IsEnabled returns true if given log level is enabled. @@ -213,7 +176,7 @@ func GetLevel(module string) Level { // SetSpec sets the log levels for individual modules as well as the default log level. // The format of the spec is as follows: // -// module1=level1:module2=level2:module3=level3:defaultLevel +// module1=level1:module2=level2:module3=level3:defaultLevel // // Valid log levels are: critical, error, warning, info, debug // @@ -362,3 +325,70 @@ func (l *moduleLevels) SetDefault(level Level) { func (l *moduleLevels) isEnabled(module string, level Level) bool { return level >= l.Get(module) } + +func newZap(module string, encoding Encoding, stdOut, stdErr zapcore.WriteSyncer) *zap.Logger { + encoder := newZapEncoder(encoding) + + core := zapcore.NewTee( + zapcore.NewCore(encoder, zapcore.Lock(stdErr), + zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { + return lvl >= zapcore.ErrorLevel && levels.isEnabled(module, Level(lvl)) + }), + ), + zapcore.NewCore(encoder, zapcore.Lock(stdOut), + zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { + return lvl < zapcore.ErrorLevel && levels.isEnabled(module, Level(lvl)) + }), + ), + ) + + return zap.New(core, zap.AddCaller()).Named(module) +} + +func newZapEncoder(encoding Encoding) zapcore.Encoder { + defaultCfg := zapcore.EncoderConfig{ + TimeKey: timestampKey, + LevelKey: levelKey, + NameKey: moduleKey, + CallerKey: callerKey, + FunctionKey: zapcore.OmitKey, + MessageKey: messageKey, + StacktraceKey: stacktraceKey, + LineEnding: zapcore.DefaultLineEnding, + EncodeLevel: zapcore.CapitalLevelEncoder, + EncodeTime: zapcore.ISO8601TimeEncoder, + EncodeDuration: zapcore.StringDurationEncoder, + EncodeCaller: zapcore.ShortCallerEncoder, + } + + switch strings.ToLower(encoding) { + case JSON: + cfg := defaultCfg + cfg.EncodeLevel = zapcore.LowercaseLevelEncoder + + return zapcore.NewJSONEncoder(cfg) + case Console: + cfg := defaultCfg + cfg.EncodeName = func(moduleName string, encoder zapcore.PrimitiveArrayEncoder) { + encoder.AppendString(fmt.Sprintf("[%s]", moduleName)) + } + + return zapcore.NewConsoleEncoder(cfg) + default: + panic("unsupported encoding " + encoding) + } +} + +func getOptions(opts []Option) *options { + options := &options{ + encoding: DefaultEncoding, + stdOut: os.Stdout, + stdErr: os.Stderr, + } + + for _, opt := range opts { + opt(options) + } + + return options +} diff --git a/internal/pkg/log/logger_test.go b/internal/pkg/log/logger_test.go index c41a66d..40ad67c 100644 --- a/internal/pkg/log/logger_test.go +++ b/internal/pkg/log/logger_test.go @@ -25,8 +25,7 @@ func newMockWriter() *mockWriter { return &mockWriter{Buffer: bytes.NewBuffer(nil)} } -// TestDefaultLogger tests default logging feature when no custom logging provider is supplied via 'Initialize()' call. -func TestDefaultLogger(t *testing.T) { +func TestLogger(t *testing.T) { const module = "sample-module" t.Run("Default level", func(t *testing.T) { @@ -35,13 +34,13 @@ func TestDefaultLogger(t *testing.T) { logger := New(module, WithStdOut(stdOut), WithStdErr(stdErr)) - logger.Debugf("Sample debug log. Some number [%d]", 123) - logger.Infof("Sample info log. Some number [%d]", 123) - logger.Warnf("Sample warn log") - logger.Errorf("Sample error log") + logger.Debug("Sample debug log") + logger.Info("Sample info log") + logger.Warn("Sample warn log") + logger.Error("Sample error log") require.Panics(t, func() { - logger.Panicf("Sample panic log") + logger.Panic("Sample panic log") }) require.NotContains(t, stdOut.Buffer.String(), "DEBUG") @@ -65,13 +64,13 @@ func TestDefaultLogger(t *testing.T) { logger := New(module, WithStdOut(stdOut), WithStdErr(stdErr)) - logger.Debugf("Sample debug log. Some number [%d]", 123) - logger.Infof("Sample info log. Some number [%d]", 123) - logger.Warnf("Sample warn log") - logger.Errorf("Sample error log") + logger.Debug("Sample debug log") + logger.Info("Sample info log") + logger.Warn("Sample warn log") + logger.Error("Sample error log") require.Panics(t, func() { - logger.Panicf("Sample panic log") + logger.Panic("Sample panic log") }) require.Contains(t, stdOut.Buffer.String(), "DEBUG") @@ -95,13 +94,13 @@ func TestDefaultLogger(t *testing.T) { logger := New(module, WithStdOut(stdOut), WithStdErr(stdErr)) - logger.Debugf("Sample debug log. Some number [%d]", 123) - logger.Infof("Sample info log. Some number [%d]", 123) - logger.Warnf("Sample warn log") - logger.Errorf("Sample error log") + logger.Debug("Sample debug log") + logger.Info("Sample info log") + logger.Warn("Sample warn log") + logger.Error("Sample error log") require.Panics(t, func() { - logger.Panicf("Sample panic log") + logger.Panic("Sample panic log") }) require.Empty(t, stdOut.Buffer.String()) diff --git a/internal/pkg/tlsutil/certpool.go b/internal/pkg/tlsutil/certpool.go index ab8d597..cf2fdd8 100644 --- a/internal/pkg/tlsutil/certpool.go +++ b/internal/pkg/tlsutil/certpool.go @@ -157,7 +157,7 @@ func loadSystemCertPool(useSystemCertPool bool) (*x509.CertPool, error) { return nil, err } - logger.Debugf("Loaded system cert pool of size: %d", len(systemCertPool.Subjects())) + logger.Debug("Loaded system cert pool", log.WithSize(len(systemCertPool.Subjects()))) return systemCertPool, nil } diff --git a/pkg/controller/rest/operation.go b/pkg/controller/rest/operation.go index 26aa0b2..68358af 100644 --- a/pkg/controller/rest/operation.go +++ b/pkg/controller/rest/operation.go @@ -315,7 +315,7 @@ func (c *Operation) HealthCheck(rw http.ResponseWriter, _ *http.Request) { Version: BuildVersion, }) if err != nil { - logger.Errorf("healthcheck response failure, %s", err) + logger.Error("Healthcheck response failure", log.WithError(err)) } } @@ -571,6 +571,6 @@ func sendError(rw http.ResponseWriter, e error) { rw.WriteHeader(errors.StatusCodeFromError(e)) if err := json.NewEncoder(rw).Encode(ErrorResponse{Message: e.Error()}); err != nil { - logger.Errorf("send error response: %v", e) + log.WriteResponseBodyError(logger, e) } } diff --git a/pkg/storage/postgres/log_storage.go b/pkg/storage/postgres/log_storage.go index d86cd24..5b55b45 100644 --- a/pkg/storage/postgres/log_storage.go +++ b/pkg/storage/postgres/log_storage.go @@ -31,6 +31,7 @@ import ( "github.com/google/trillian/storage/cache" trilliantree "github.com/google/trillian/storage/tree" "github.com/google/trillian/types" + "github.com/trustbloc/vct/internal/pkg/log" "google.golang.org/grpc/codes" "google.golang.org/grpc/status" "google.golang.org/protobuf/types/known/timestamppb" @@ -517,7 +518,7 @@ func (t *logTreeTX) QueueLeaves(ctx context.Context, leaves []*trillian.LogLeaf, existingCount++ queuedDupCounter.Inc(label) - logger.Warnf("Found duplicate %v %v", t.treeID, leaf) + logger.Warn("Found duplicate", log.WithTreeID(t.treeID), log.WithLeaf(leaf)) continue } diff --git a/pkg/storage/postgres/provider.go b/pkg/storage/postgres/provider.go index b574daa..c58f5e6 100644 --- a/pkg/storage/postgres/provider.go +++ b/pkg/storage/postgres/provider.go @@ -57,7 +57,7 @@ func NewPGProvider(mf monitoring.MetricFactory) (storage.Provider, error) { } func (s *pgProvider) LogStorage() storage.LogStorage { - logger.Warnf("Support for the PostgreSQL log is experimental. Please use at your own risk!!!") + logger.Warn("Support for the PostgreSQL log is experimental. Please use at your own risk!!!") return NewLogStorage(s.db, s.mf) } diff --git a/pkg/storage/postgres/testdb/testdb.go b/pkg/storage/postgres/testdb/testdb.go index da12587..8dba308 100644 --- a/pkg/storage/postgres/testdb/testdb.go +++ b/pkg/storage/postgres/testdb/testdb.go @@ -83,7 +83,7 @@ func newEmptyDB(ctx context.Context) (*sql.DB, func(context.Context), error) { db, err = sql.Open("postgres", getConnStr("test")) if _, err := db.ExecContext(ctx, fmt.Sprintf("DROP DATABASE %v WITH (FORCE);", name)); err != nil { - logger.Warnf("Failed to drop test database %q: %v", name, err) + logger.Warn("Failed to drop test database", log.WithStore(name), log.WithError(err)) } db.Close() // nolint: errcheck, gosec diff --git a/test/bdd/bddtests_test.go b/test/bdd/bddtests_test.go index c5f4f8b..40c6f4e 100644 --- a/test/bdd/bddtests_test.go +++ b/test/bdd/bddtests_test.go @@ -66,15 +66,19 @@ var ( func runBddTests(tags, format string) int { return godog.RunWithOptions("godogs", func(s *godog.Suite) { s.BeforeSuite(func() { - logger.Infof("Running %s", strings.Join(dockerComposeUp, " ")) + logger.Info("Running command", log.WithCommand(strings.Join(dockerComposeUp, " "))) + if err := exec.Command(dockerComposeUp[0], dockerComposeUp[1:]...).Run(); err != nil { //nolint: gosec - logger.Errorf("command %q failed: %w", strings.Join(dockerComposeUp, " "), err) + logger.Error("Command", log.WithCommand(strings.Join(dockerComposeUp, " ")), + log.WithError(err)) } }) s.AfterSuite(func() { - logger.Infof("Running %s", strings.Join(dockerComposeDown, " ")) + logger.Info("Running command", log.WithCommand(strings.Join(dockerComposeDown, " "))) + if err := exec.Command(dockerComposeDown[0], dockerComposeDown[1:]...).Run(); err != nil { //nolint: gosec - logger.Errorf("command %q failed: %w", strings.Join(dockerComposeDown, " "), err) + logger.Error("Command failed", log.WithCommand(strings.Join(dockerComposeDown, " ")), + log.WithError(err)) } }) featureContext(s) diff --git a/test/bdd/pkg/controller/rest/rest_controller_steps.go b/test/bdd/pkg/controller/rest/rest_controller_steps.go index 1d7d7a0..0fbaae4 100644 --- a/test/bdd/pkg/controller/rest/rest_controller_steps.go +++ b/test/bdd/pkg/controller/rest/rest_controller_steps.go @@ -243,8 +243,9 @@ func (s *Steps) addVC(file string) error { s.state.AddedCredentials[file] = resp - logger.Infof("Successfully verified VC timestamp signature for VC %s - Signature: %s, Timestamp: %d, Public Key: %s", - src, resp.Signature, resp.Timestamp, webResp.Properties[command.PublicKeyType]) + logger.Info("Successfully verified VC timestamp signature", log.WithVerifiableCredential(src), + log.WithSignature(resp.Signature), log.WithTimestamp(resp.Timestamp), + log.WithPublicKey(webResp.Properties[command.PublicKeyType])) return nil }