Skip to content

Commit

Permalink
Merge pull request #131 from bstasyszyn/130
Browse files Browse the repository at this point in the history
chore: Use structured logging
  • Loading branch information
bstasyszyn authored Oct 5, 2022
2 parents 8b6a133 + e1012e2 commit acba000
Show file tree
Hide file tree
Showing 18 changed files with 490 additions and 149 deletions.
22 changes: 11 additions & 11 deletions cmd/internal/serverutil/serverutil.go
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand All @@ -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 != "" {
Expand All @@ -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 {
Expand All @@ -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,
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand Down
6 changes: 3 additions & 3 deletions cmd/log_server/main.go
Original file line number Diff line number Diff line change
Expand Up @@ -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{
Expand All @@ -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))
}
}
10 changes: 5 additions & 5 deletions cmd/log_signer/main.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
)
Expand Down Expand Up @@ -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{
Expand All @@ -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))
}
}
4 changes: 2 additions & 2 deletions cmd/vct/main.go
Original file line number Diff line number Diff line change
Expand Up @@ -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))
}
}
17 changes: 10 additions & 7 deletions cmd/vct/startcmd/start.go
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
Expand Down Expand Up @@ -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))
}
}()

Expand Down Expand Up @@ -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,
Expand All @@ -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))
}
}

Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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))
})
}

Expand Down
14 changes: 14 additions & 0 deletions internal/pkg/log/common.go
Original file line number Diff line number Diff line change
@@ -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))
}
34 changes: 34 additions & 0 deletions internal/pkg/log/common_test.go
Original file line number Diff line number Diff line change
@@ -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")
})
}
117 changes: 117 additions & 0 deletions internal/pkg/log/fields.go
Original file line number Diff line number Diff line change
@@ -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)
}
Loading

0 comments on commit acba000

Please sign in to comment.