chore: Use structured logging

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

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

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

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

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

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

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")
+	})
+}

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