log: improve logging

- add a panic recovery handler
        - add logs on unexpected error paths
        - use logger's panic method

pkg/api/BUILD.bazel

@@ -8,7 +8,6 @@ go_library(
         "controller.go",
         "errors.go",
         "ldap.go",
-        "log.go",
         "regexp.go",
         "routes.go",
     ],
@@ -17,14 +16,15 @@ go_library(
     deps = [
         "//docs:go_default_library",
         "//errors:go_default_library",
+        "//pkg/log:go_default_library",
         "//pkg/storage:go_default_library",
         "@com_github_getlantern_deepcopy//:go_default_library",
+        "@com_github_gorilla_handlers//:go_default_library",
         "@com_github_gorilla_mux//:go_default_library",
         "@com_github_json_iterator_go//:go_default_library",
         "@com_github_jtblin_go_ldap_client//:go_default_library",
         "@com_github_opencontainers_distribution_spec//:go_default_library",
         "@com_github_opencontainers_image_spec//specs-go/v1:go_default_library",
-        "@com_github_rs_zerolog//:go_default_library",
         "@com_github_swaggo_http_swagger//:go_default_library",
         "@in_gopkg_ldap_v2//:go_default_library",
         "@org_golang_x_crypto//bcrypt:go_default_library",

pkg/api/config.go

@@ -2,9 +2,9 @@ package api
 
 import (
 	"github.com/anuvu/zot/errors"
+	"github.com/anuvu/zot/pkg/log"
 	"github.com/getlantern/deepcopy"
 	dspec "github.com/opencontainers/distribution-spec"
-	"github.com/rs/zerolog"
 )
 
 //nolint (gochecknoglobals)
@@ -92,7 +92,7 @@ func (c *Config) Sanitize() *Config {
 	return c
 }
 
-func (c *Config) Validate(log zerolog.Logger) error {
+func (c *Config) Validate(log log.Logger) error {
 	// LDAP configuration
 	if c.HTTP.Auth != nil && c.HTTP.Auth.LDAP != nil {
 		l := c.HTTP.Auth.LDAP

pkg/api/controller.go

@@ -9,21 +9,22 @@ import (
 	"net/http"
 
 	"github.com/anuvu/zot/errors"
+	"github.com/anuvu/zot/pkg/log"
 	"github.com/anuvu/zot/pkg/storage"
+	"github.com/gorilla/handlers"
 	"github.com/gorilla/mux"
-	"github.com/rs/zerolog"
 )
 
 type Controller struct {
 	Config     *Config
 	Router     *mux.Router
 	ImageStore *storage.ImageStore
-	Log        zerolog.Logger
+	Log        log.Logger
 	Server     *http.Server
 }
 
 func NewController(config *Config) *Controller {
-	return &Controller{Config: config, Log: NewLogger(config)}
+	return &Controller{Config: config, Log: log.NewLogger(config.Log.Level, config.Log.Output)}
 }
 
 func (c *Controller) Run() error {
@@ -37,7 +38,8 @@ func (c *Controller) Run() error {
 	c.Log.Info().Interface("params", c.Config.Sanitize()).Msg("configuration settings")
 
 	engine := mux.NewRouter()
-	engine.Use(Logger(c.Log))
+	engine.Use(log.SessionLogger(c.Log), handlers.RecoveryHandler(handlers.RecoveryLogger(c.Log),
+		handlers.PrintRecoveryStack(false)))
 	c.Router = engine
 	_ = NewRouteHandler(c)
 

pkg/api/ldap.go

@@ -7,8 +7,8 @@ import (
 	"time"
 
 	"github.com/anuvu/zot/errors"
+	"github.com/anuvu/zot/pkg/log"
 	"github.com/jtblin/go-ldap-client"
-	"github.com/rs/zerolog"
 	goldap "gopkg.in/ldap.v2"
 )
 
@@ -18,7 +18,7 @@ type LDAPClient struct {
 	ldap.LDAPClient
 	subtreeSearch bool
 	clientCAs     *x509.CertPool
-	log           zerolog.Logger
+	log           log.Logger
 }
 
 // Connect connects to the ldap backend.

pkg/api/log.go

@@ -1,99 +0,0 @@
-package api
-
-import (
-	"net/http"
-	"os"
-	"time"
-
-	"github.com/gorilla/mux"
-	"github.com/rs/zerolog"
-)
-
-func NewLogger(config *Config) zerolog.Logger {
-	zerolog.TimeFieldFormat = time.RFC3339Nano
-	lvl, err := zerolog.ParseLevel(config.Log.Level)
-	if err != nil {
-		panic(err)
-	}
-	zerolog.SetGlobalLevel(lvl)
-	var log zerolog.Logger
-	if config.Log.Output == "" {
-		log = zerolog.New(os.Stdout)
-	} else {
-		file, err := os.OpenFile(config.Log.Output, os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0600)
-		if err != nil {
-			panic(err)
-		}
-		log = zerolog.New(file)
-	}
-	return log.With().Timestamp().Logger()
-}
-
-type statusWriter struct {
-	http.ResponseWriter
-	status int
-	length int
-}
-
-func (w *statusWriter) WriteHeader(status int) {
-	w.status = status
-	w.ResponseWriter.WriteHeader(status)
-}
-
-func (w *statusWriter) Write(b []byte) (int, error) {
-	if w.status == 0 {
-		w.status = 200
-	}
-	n, err := w.ResponseWriter.Write(b)
-	w.length += n
-	return n, err
-}
-
-func Logger(log zerolog.Logger) mux.MiddlewareFunc {
-	l := log.With().Str("module", "http").Logger()
-	return func(next http.Handler) http.Handler {
-		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-			// Start timer
-			start := time.Now()
-			path := r.URL.Path
-			raw := r.URL.RawQuery
-
-			sw := statusWriter{ResponseWriter: w}
-
-			// Process request
-			next.ServeHTTP(&sw, r)
-
-			// Stop timer
-			end := time.Now()
-			latency := end.Sub(start)
-			if latency > time.Minute {
-				// Truncate in a golang < 1.8 safe way
-				latency -= latency % time.Second
-			}
-			clientIP := r.RemoteAddr
-			method := r.Method
-			headers := map[string][]string{}
-			for key, value := range r.Header {
-				if key == "Authorization" { // anonymize from logs
-					value = []string{"******"}
-				}
-				headers[key] = value
-			}
-			statusCode := sw.status
-			bodySize := sw.length
-			if raw != "" {
-				path = path + "?" + raw
-			}
-
-			l.Info().
-				Str("clientIP", clientIP).
-				Str("method", method).
-				Str("path", path).
-				Int("statusCode", statusCode).
-				Str("latency", latency.String()).
-				Int("bodySize", bodySize).
-				Interface("headers", headers).
-				Msg("HTTP API")
-		})
-	}
-}

pkg/api/routes.go

@@ -162,6 +162,7 @@ func (rh *RouteHandler) CheckManifest(w http.ResponseWriter, r *http.Request) {
 		case errors.ErrManifestNotFound:
 			WriteJSON(w, http.StatusNotFound, NewError(MANIFEST_UNKNOWN, map[string]string{"reference": reference}))
 		default:
+			rh.c.Log.Error().Err(err).Msg("unexpected error")
 			WriteJSON(w, http.StatusInternalServerError, NewError(MANIFEST_INVALID, map[string]string{"reference": reference}))
 		}
 		return
@@ -213,6 +214,7 @@ func (rh *RouteHandler) GetManifest(w http.ResponseWriter, r *http.Request) {
 		case errors.ErrManifestNotFound:
 			WriteJSON(w, http.StatusNotFound, NewError(MANIFEST_UNKNOWN, map[string]string{"reference": reference}))
 		default:
+			rh.c.Log.Error().Err(err).Msg("unexpected error")
 			w.WriteHeader(http.StatusInternalServerError)
 		}
 		return
@@ -273,6 +275,7 @@ func (rh *RouteHandler) UpdateManifest(w http.ResponseWriter, r *http.Request) {
 		case errors.ErrBlobNotFound:
 			WriteJSON(w, http.StatusBadRequest, NewError(BLOB_UNKNOWN, map[string]string{"blob": digest}))
 		default:
+			rh.c.Log.Error().Err(err).Msg("unexpected error")
 			w.WriteHeader(http.StatusInternalServerError)
 		}
 		return
@@ -314,6 +317,7 @@ func (rh *RouteHandler) DeleteManifest(w http.ResponseWriter, r *http.Request) {
 		case errors.ErrManifestNotFound:
 			WriteJSON(w, http.StatusNotFound, NewError(MANIFEST_UNKNOWN, map[string]string{"reference": reference}))
 		default:
+			rh.c.Log.Error().Err(err).Msg("unexpected error")
 			w.WriteHeader(http.StatusInternalServerError)
 		}
 		return
@@ -358,6 +362,7 @@ func (rh *RouteHandler) CheckBlob(w http.ResponseWriter, r *http.Request) {
 		case errors.ErrBlobNotFound:
 			WriteJSON(w, http.StatusNotFound, NewError(BLOB_UNKNOWN, map[string]string{"digest": digest}))
 		default:
+			rh.c.Log.Error().Err(err).Msg("unexpected error")
 			w.WriteHeader(http.StatusInternalServerError)
 		}
 		return
@@ -409,6 +414,7 @@ func (rh *RouteHandler) GetBlob(w http.ResponseWriter, r *http.Request) {
 		case errors.ErrBlobNotFound:
 			WriteJSON(w, http.StatusNotFound, NewError(BLOB_UNKNOWN, map[string]string{"digest": digest}))
 		default:
+			rh.c.Log.Error().Err(err).Msg("unexpected error")
 			w.WriteHeader(http.StatusInternalServerError)
 		}
 		return
@@ -453,6 +459,7 @@ func (rh *RouteHandler) DeleteBlob(w http.ResponseWriter, r *http.Request) {
 		case errors.ErrBlobNotFound:
 			WriteJSON(w, http.StatusNotFound, NewError(BLOB_UNKNOWN, map[string]string{"digest": digest}))
 		default:
+			rh.c.Log.Error().Err(err).Msg("unexpected error")
 			w.WriteHeader(http.StatusInternalServerError)
 		}
 		return
@@ -487,6 +494,7 @@ func (rh *RouteHandler) CreateBlobUpload(w http.ResponseWriter, r *http.Request)
 		case errors.ErrRepoNotFound:
 			WriteJSON(w, http.StatusNotFound, NewError(NAME_UNKNOWN, map[string]string{"name": name}))
 		default:
+			rh.c.Log.Error().Err(err).Msg("unexpected error")
 			w.WriteHeader(http.StatusInternalServerError)
 		}
 		return
@@ -536,6 +544,7 @@ func (rh *RouteHandler) GetBlobUpload(w http.ResponseWriter, r *http.Request) {
 		case errors.ErrUploadNotFound:
 			WriteJSON(w, http.StatusNotFound, NewError(BLOB_UPLOAD_UNKNOWN, map[string]string{"uuid": uuid}))
 		default:
+			rh.c.Log.Error().Err(err).Msg("unexpected error")
 			w.WriteHeader(http.StatusInternalServerError)
 		}
 		return
@@ -613,6 +622,7 @@ func (rh *RouteHandler) PatchBlobUpload(w http.ResponseWriter, r *http.Request)
 		case errors.ErrUploadNotFound:
 			WriteJSON(w, http.StatusNotFound, NewError(BLOB_UPLOAD_UNKNOWN, map[string]string{"uuid": uuid}))
 		default:
+			rh.c.Log.Error().Err(err).Msg("unexpected error")
 			w.WriteHeader(http.StatusInternalServerError)
 		}
 		return
@@ -708,6 +718,7 @@ func (rh *RouteHandler) UpdateBlobUpload(w http.ResponseWriter, r *http.Request)
 			case errors.ErrUploadNotFound:
 				WriteJSON(w, http.StatusNotFound, NewError(BLOB_UPLOAD_UNKNOWN, map[string]string{"uuid": uuid}))
 			default:
+				rh.c.Log.Error().Err(err).Msg("unexpected error")
 				w.WriteHeader(http.StatusInternalServerError)
 			}
 			return
@@ -726,6 +737,7 @@ func (rh *RouteHandler) UpdateBlobUpload(w http.ResponseWriter, r *http.Request)
 		case errors.ErrUploadNotFound:
 			WriteJSON(w, http.StatusNotFound, NewError(BLOB_UPLOAD_UNKNOWN, map[string]string{"uuid": uuid}))
 		default:
+			rh.c.Log.Error().Err(err).Msg("unexpected error")
 			w.WriteHeader(http.StatusInternalServerError)
 		}
 		return
@@ -769,6 +781,7 @@ func (rh *RouteHandler) DeleteBlobUpload(w http.ResponseWriter, r *http.Request)
 		case errors.ErrUploadNotFound:
 			WriteJSON(w, http.StatusNotFound, NewError(BLOB_UPLOAD_UNKNOWN, map[string]string{"uuid": uuid}))
 		default:
+			rh.c.Log.Error().Err(err).Msg("unexpected error")
 			w.WriteHeader(http.StatusInternalServerError)
 		}
 		return