Add structured logging using zap (#2)

.gitignore

@@ -1,5 +1,5 @@
-internal/server
-api/openapi.yaml
-.history/
 zero-notification-service
-
+.history/
+api/openapi.yaml
+internal/server/*
+!internal/server/logger.go

.openapi-generator-ignore

@@ -26,3 +26,4 @@ main.go
 go.mod
 README.md
 Dockerfile
+internal/server/logger.go

.openapi-generator/FILES

@@ -8,7 +8,6 @@ internal/server/api_notification.go
 internal/server/api_notification_service.go
 internal/server/helpers.go
 internal/server/impl.go
-internal/server/logger.go
 internal/server/model_error.go
 internal/server/model_mail_message.go
 internal/server/model_notification_message.go

cmd/server/main.go

@@ -12,16 +12,17 @@ package main
 import (
 	"context"
 	"fmt"
-	"log"
 	"net/http"
 	"os"
 	"os/signal"
 	"syscall"
 	"time"
 
 	"github.com/commitdev/zero-notification-service/internal/config"
+	"github.com/commitdev/zero-notification-service/internal/log"
 	"github.com/commitdev/zero-notification-service/internal/server"
 	"github.com/commitdev/zero-notification-service/internal/service"
+	"go.uber.org/zap"
 )
 
 var (
@@ -30,13 +31,16 @@ var (
 )
 
 func main() {
-	fmt.Printf("zero-notification-service version: %v, build: %v \n", appVersion, appBuild)
+	config := config.GetConfig()
+
+	log.Init(config)
+	defer zap.S().Sync() // Flush logs when the process ends
+
+	zap.S().Infow("zero-notification-service", "version", appVersion, "build", appBuild)
 
 	// Heartbeat for liveness check
 	go heartbeat()
 
-	config := config.GetConfig()
-
 	EmailApiService := service.NewEmailApiService(config)
 	EmailApiController := server.NewEmailApiController(EmailApiService)
 
@@ -57,34 +61,34 @@ func main() {
 
 	// Run the server in a goroutine
 	go func() {
-		log.Printf("Serving at http://%s/", serverAddress)
+		zap.S().Infof("Serving at http://%s/", serverAddress)
 		err := server.ListenAndServe()
 		if err != http.ErrServerClosed {
-			log.Fatalf("Fatal error while serving HTTP: %v\n", err)
+			zap.S().Fatalf("Fatal error while serving HTTP: %v\n", err)
 			close(stop)
 		}
 	}()
 
 	// Block while reading from the channel until we receive a signal
 	sig := <-stop
-	log.Printf("Received signal %s, starting graceful shutdown", sig)
+	zap.S().Infof("Received signal %s, starting graceful shutdown", sig)
 
 	// Give connections some time to drain
 	ctx, cancel := context.WithTimeout(context.Background(), config.GracefulShutdownTimeout*time.Second)
 	defer cancel()
 	err := server.Shutdown(ctx)
 	if err != nil {
-		log.Fatalf("Error during shutdown, client requests have been terminated: %v\n", err)
+		zap.S().Fatalf("Error during shutdown, client requests have been terminated: %v\n", err)
 	} else {
-		log.Println("Graceful shutdown complete")
+		zap.S().Infof("Graceful shutdown complete")
 	}
 }
 
 func heartbeat() {
 	for range time.Tick(4 * time.Second) {
 		fh, err := os.Create("/tmp/service-alive")
 		if err != nil {
-			log.Println("Unable to write file for liveness check!")
+			zap.S().Warnf("Unable to write file for liveness check!")
 		} else {
 			fh.Close()
 		}

go.mod

@@ -4,10 +4,12 @@ go 1.15
 
 require (
 	github.com/gorilla/mux v1.7.3
+	github.com/pkg/errors v0.9.1 // indirect
 	github.com/sendgrid/rest v2.6.2+incompatible
 	github.com/sendgrid/sendgrid-go v3.7.2+incompatible
 	github.com/spf13/viper v1.7.1
-	github.com/stretchr/testify v1.3.0
-	golang.org/x/sys v0.0.0-20200930185726-fdedc70b468f // indirect
-	golang.org/x/text v0.3.3 // indirect
+	github.com/stretchr/testify v1.4.0
+	go.uber.org/multierr v1.6.0 // indirect
+	go.uber.org/zap v1.16.0
+	golang.org/x/tools v0.0.0-20201208002638-66f931576d67 // indirect
 )

internal/config/config.go

@@ -11,6 +11,7 @@ type Config struct {
 	Port                    int
 	SendgridAPIKey          string
 	GracefulShutdownTimeout time.Duration
+	StructuredLogging       bool
 }
 
 var config *Config
@@ -20,6 +21,7 @@ const (
 	Port
 	SendgridAPIKey
 	GracefulShutdownTimeout
+	StructuredLogging
 )
 
 // GetConfig returns a pointer to the singleton Config object
@@ -40,10 +42,14 @@ func loadConfig() *Config {
 	viper.SetDefault(GracefulShutdownTimeout, "10")
 	viper.BindEnv(GracefulShutdownTimeout, "GRACEFUL_SHUTDOWN_TIMEOUT_SECONDS")
 
+	viper.SetDefault(StructuredLogging, "false")
+	viper.BindEnv(StructuredLogging, "STRUCTURED_LOGGING")
+
 	config := Config{
 		Port:                    viper.GetInt(Port),
 		SendgridAPIKey:          viper.GetString(SendgridAPIKey),
 		GracefulShutdownTimeout: viper.GetDuration(GracefulShutdownTimeout),
+		StructuredLogging:       viper.GetBool(StructuredLogging),
 	}
 
 	return &config

internal/log/ecs.go

@@ -0,0 +1,62 @@
+// Helpers for ECS log formatting
+// https://www.elastic.co/guide/en/ecs/master/index.html
+package log
+
+import (
+	"time"
+
+	"go.uber.org/zap/zapcore"
+)
+
+// ECSHTTP represents a subset of the fields of the ECS HTTP object
+type ECSHTTP struct {
+	Request  ECSRequest
+	Response ECSResponse
+}
+
+func (o ECSHTTP) MarshalLogObject(enc zapcore.ObjectEncoder) error {
+	enc.AddObject("request", o.Request)
+	return enc.AddObject("response", o.Response)
+}
+
+// ECSResponse represents a subset of the fields of the ECS HTTP Response object
+type ECSResponse struct {
+	StatusCode int
+}
+
+func (o ECSResponse) MarshalLogObject(enc zapcore.ObjectEncoder) error {
+	enc.AddInt("status_code", o.StatusCode)
+	return nil
+}
+
+// ECSRequest represents a subset of the fields of the ECS HTTP Request object
+type ECSRequest struct {
+	Method string
+}
+
+func (o ECSRequest) MarshalLogObject(enc zapcore.ObjectEncoder) error {
+	enc.AddString("method", o.Method)
+	return nil
+}
+
+// ECSURL represents a subset of the fields of the ECS URL object
+type ECSURL struct {
+	Original string
+}
+
+func (o ECSURL) MarshalLogObject(enc zapcore.ObjectEncoder) error {
+	enc.AddString("original", o.Original)
+	return nil
+}
+
+// ECSEvent represents a subset of the fields of the ECS Event object
+type ECSEvent struct {
+	Action   string
+	Duration time.Duration
+}
+
+func (o ECSEvent) MarshalLogObject(enc zapcore.ObjectEncoder) error {
+	enc.AddString("action", o.Action)
+	enc.AddInt64("duration", int64(o.Duration))
+	return nil
+}

internal/log/log.go

@@ -0,0 +1,33 @@
+package log
+
+import (
+	"log"
+
+	"github.com/commitdev/zero-notification-service/internal/config"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+)
+
+// Init sets up logging based on the current environment
+func Init(config *config.Config) {
+	var rawLogger *zap.Logger
+	var err error
+	if config.StructuredLogging {
+		// Info level, JSON output
+		zapConfig := zap.NewProductionConfig()
+		zapConfig.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
+		zapConfig.EncoderConfig.MessageKey = "message"
+		rawLogger, err = zapConfig.Build()
+	} else {
+		// Debug level, pretty output
+		zapConfig := zap.NewDevelopmentConfig()
+		zapConfig.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
+		rawLogger, err = zapConfig.Build()
+	}
+
+	if err != nil {
+		log.Fatalf("can't initialize zap logger: %v", err)
+	}
+
+	zap.ReplaceGlobals(rawLogger)
+}

internal/mail/mail.go

@@ -32,7 +32,7 @@ func SendBulkMail(toList []server.Recipient, from server.Sender, message server.
 			wg.Done()
 		}(to)
 	}
-	// Wait on the all responses to close the channel to signal that the operation is complete
+	// Wait on all the responses to close the channel to signal that the operation is complete
 	go func() {
 		wg.Wait()
 		close(responseChannel)

internal/server/logger.go

@@ -0,0 +1,62 @@
+/*
+ * Zero Notification Service
+ *
+ * No description provided (generated by Openapi Generator https://github.com/openapitools/openapi-generator)
+ *
+ * API version: 1.0.0
+ * Generated by: OpenAPI Generator (https://openapi-generator.tech)
+ */
+
+package server
+
+import (
+	"net/http"
+	"time"
+
+	"github.com/commitdev/zero-notification-service/internal/config"
+	"github.com/commitdev/zero-notification-service/internal/log"
+	"go.uber.org/zap"
+)
+
+// HTTP Reponse Writer with a little wrapper to collect the status code
+type loggingResponseWriter struct {
+	http.ResponseWriter
+	statusCode int
+}
+
+func (lrw *loggingResponseWriter) WriteHeader(code int) {
+	lrw.statusCode = code
+	lrw.ResponseWriter.WriteHeader(code)
+}
+
+func Logger(inner http.Handler, name string) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		start := time.Now()
+
+		lrw := &loggingResponseWriter{w, http.StatusOK}
+		inner.ServeHTTP(lrw, r)
+
+		if config.GetConfig().StructuredLogging {
+			http := log.ECSHTTP{
+				Request: log.ECSRequest{
+					Method: r.Method,
+				},
+				Response: log.ECSResponse{
+					StatusCode: lrw.statusCode,
+				},
+			}
+			url := log.ECSURL{Original: r.RequestURI}
+			event := log.ECSEvent{Action: name, Duration: time.Since(start)}
+
+			zap.S().Infow("HTTP Request", zap.Any("http", http), zap.Any("url", url), zap.Any("event", event))
+		} else {
+			zap.S().Infow("HTTP Request",
+				"method", r.Method,
+				"status_code", lrw.statusCode,
+				"url", r.RequestURI,
+				"action", name,
+				"duration", time.Since(start),
+			)
+		}
+	})
+}