logging improvements (#20)

* enhancement: Added request id logging, added logging for 4xx errors since they weren't caught by route-specific logging

* enhancement: Added the ability to dump request content for debugging

* Update internal/log/ecs.go

Co-authored-by: David Cheung <[email protected]>

Co-authored-by: David Cheung <[email protected]>

Author: bmonkman

cmd/server/main.go

@@ -50,7 +50,7 @@ func main() {
 	NotificationApiService := service.NewNotificationApiService(config)
 	NotificationApiController := server.NewNotificationApiController(NotificationApiService)
 
-	router := server.NewRouter(EmailApiController, HealthApiController, NotificationApiController)
+	router := server.Logger(server.NewRouter(EmailApiController, HealthApiController, NotificationApiController), "")
 
 	serverAddress := fmt.Sprintf("0.0.0.0:%d", config.Port)
 	server := &http.Server{Addr: serverAddress, Handler: router}

internal/config/config.go

@@ -13,6 +13,7 @@ type Config struct {
 	SlackAPIKey             string
 	GracefulShutdownTimeout time.Duration
 	StructuredLogging       bool
+	DebugDumpRequests       bool
 }
 
 var config *Config
@@ -24,6 +25,7 @@ const (
 	SlackAPIKey
 	GracefulShutdownTimeout
 	StructuredLogging
+	DebugDumpRequests
 )
 
 // GetConfig returns a pointer to the singleton Config object
@@ -50,12 +52,16 @@ func loadConfig() *Config {
 	viper.SetDefault(StructuredLogging, "false")
 	viper.BindEnv(StructuredLogging, "STRUCTURED_LOGGING")
 
+	viper.SetDefault(DebugDumpRequests, "false")
+	viper.BindEnv(DebugDumpRequests, "DEBUG_DUMP_REQUESTS")
+
 	config := Config{
 		Port:                    viper.GetInt(Port),
 		SendgridAPIKey:          viper.GetString(SendgridAPIKey),
 		SlackAPIKey:             viper.GetString(SlackAPIKey),
 		GracefulShutdownTimeout: viper.GetDuration(GracefulShutdownTimeout),
 		StructuredLogging:       viper.GetBool(StructuredLogging),
+		DebugDumpRequests:       viper.GetBool(DebugDumpRequests),
 	}
 
 	return &config

internal/log/ecs.go

@@ -60,3 +60,13 @@ func (o ECSEvent) MarshalLogObject(enc zapcore.ObjectEncoder) error {
 	enc.AddInt64("duration", int64(o.Duration))
 	return nil
 }
+
+// ECSTrace represents a subset of the fields of the ECS Trace object
+type ECSTrace struct {
+	ID string
+}
+
+func (o ECSTrace) MarshalLogObject(enc zapcore.ObjectEncoder) error {
+	enc.AddString("id", o.ID)
+	return nil
+}

internal/server/logger.go

@@ -11,6 +11,7 @@ package server
 
 import (
 	"net/http"
+	"net/http/httputil"
 	"time"
 
 	"github.com/commitdev/zero-notification-service/internal/config"
@@ -33,9 +34,23 @@ func Logger(inner http.Handler, name string) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		start := time.Now()
 
+		// If configured, dump the content of the request for debugging
+		if config.GetConfig().DebugDumpRequests {
+			requestDump, err := httputil.DumpRequest(r, true)
+			if err != nil {
+				zap.S().Errorw("Error getting request content", err)
+			}
+			zap.S().Debugw("HTTP Request Content", zap.ByteString("content", requestDump))
+		}
+
 		lrw := &loggingResponseWriter{w, http.StatusOK}
 		inner.ServeHTTP(lrw, r)
 
+		// Use the global handler for 4xx status codes, as there won't be a route-specific one
+		if !(lrw.statusCode >= 400 && lrw.statusCode <= 499) && name == "" {
+			return
+		}
+
 		if config.GetConfig().StructuredLogging {
 			// Don't log health checks in a cloud environment - name is defined in the schema
 			if name != "ReadyCheck" {
@@ -49,8 +64,9 @@ func Logger(inner http.Handler, name string) http.Handler {
 				}
 				url := log.ECSURL{Original: r.RequestURI}
 				event := log.ECSEvent{Action: name, Duration: time.Since(start)}
+				trace := log.ECSTrace{ID: r.Header.Get("X-Request-ID")}
 
-				zap.S().Infow("HTTP Request", zap.Any("http", http), zap.Any("url", url), zap.Any("event", event))
+				zap.S().Infow("HTTP Request", zap.Any("http", http), zap.Any("url", url), zap.Any("event", event), zap.Any("trace", trace))
 			}
 		} else {
 			zap.S().Infow("HTTP Request",
@@ -59,6 +75,7 @@ func Logger(inner http.Handler, name string) http.Handler {
 				"url", r.RequestURI,
 				"action", name,
 				"duration", time.Since(start),
+				"request_id", r.Header.Get("X-Request-ID"),
 			)
 		}
 	})