Merge pull request #798 from docker/server-logging

Add info logging for 400s, error for 500s, adjust timestamp error level on GetCurrent

server/handlers/default.go

@@ -7,7 +7,6 @@ import (
 	"net/http"
 	"strings"
 
-	"github.com/Sirupsen/logrus"
 	ctxu "github.com/docker/distribution/context"
 	"github.com/gorilla/mux"
 	"golang.org/x/net/context"
@@ -61,6 +60,7 @@ func atomicUpdateHandler(ctx context.Context, w http.ResponseWriter, r *http.Req
 
 	reader, err := r.MultipartReader()
 	if err != nil {
+		logger.Info("400 POST unable to parse TUF data")
 		return errors.ErrMalformedUpload.WithDetail(nil)
 	}
 	var updates []storage.MetaUpdate
@@ -71,8 +71,10 @@ func atomicUpdateHandler(ctx context.Context, w http.ResponseWriter, r *http.Req
 		}
 		role := strings.TrimSuffix(part.FileName(), ".json")
 		if role == "" {
+			logger.Info("400 POST empty role")
 			return errors.ErrNoFilename.WithDetail(nil)
 		} else if !data.ValidRole(role) {
+			logger.Infof("400 POST invalid role: %s", role)
 			return errors.ErrInvalidRole.WithDetail(role)
 		}
 		meta := &data.SignedMeta{}
@@ -81,6 +83,7 @@ func atomicUpdateHandler(ctx context.Context, w http.ResponseWriter, r *http.Req
 		dec := json.NewDecoder(io.TeeReader(part, inBuf))
 		err = dec.Decode(meta)
 		if err != nil {
+			logger.Info("400 POST malformed update JSON")
 			return errors.ErrMalformedJSON.WithDetail(nil)
 		}
 		version := meta.Signed.Version
@@ -94,6 +97,7 @@ func atomicUpdateHandler(ctx context.Context, w http.ResponseWriter, r *http.Req
 	if err != nil {
 		serializable, serializableError := validation.NewSerializableError(err)
 		if serializableError != nil {
+			logger.Info("400 POST error validating update")
 			return errors.ErrInvalidUpdate.WithDetail(nil)
 		}
 		return errors.ErrInvalidUpdate.WithDetail(serializable)
@@ -102,6 +106,7 @@ func atomicUpdateHandler(ctx context.Context, w http.ResponseWriter, r *http.Req
 	if err != nil {
 		// If we have an old version error, surface to user with error code
 		if _, ok := err.(storage.ErrOldVersion); ok {
+			logger.Info("400 POST old version error")
 			return errors.ErrOldVersion.WithDetail(err)
 		}
 		// More generic storage update error, possibly due to attempted rollback
@@ -124,13 +129,17 @@ func getHandler(ctx context.Context, w http.ResponseWriter, r *http.Request, var
 	tufRole := vars["tufRole"]
 	s := ctx.Value("metaStore")
 
+	logger := ctxu.GetLoggerWithField(ctx, gun, "gun")
+
 	store, ok := s.(storage.MetaStore)
 	if !ok {
+		logger.Error("500 GET: no storage exists")
 		return errors.ErrNoStorage.WithDetail(nil)
 	}
 
 	lastModified, output, err := getRole(ctx, store, gun, tufRole, checksum)
 	if err != nil {
+		logger.Infof("404 GET %s role", tufRole)
 		return err
 	}
 	if lastModified != nil {
@@ -139,7 +148,7 @@ func getHandler(ctx context.Context, w http.ResponseWriter, r *http.Request, var
 		// of time.
 		utils.SetLastModifiedHeader(w.Header(), *lastModified)
 	} else {
-		logrus.Warnf("Got bytes out for %s's %s (checksum: %s), but missing lastModified date",
+		logger.Warnf("Got bytes out for %s's %s (checksum: %s), but missing lastModified date",
 			gun, tufRole, checksum)
 	}
 
@@ -149,14 +158,15 @@ func getHandler(ctx context.Context, w http.ResponseWriter, r *http.Request, var
 
 // DeleteHandler deletes all data for a GUN. A 200 responses indicates success.
 func DeleteHandler(ctx context.Context, w http.ResponseWriter, r *http.Request) error {
+	vars := mux.Vars(r)
+	gun := vars["imageName"]
+	logger := ctxu.GetLoggerWithField(ctx, gun, "gun")
 	s := ctx.Value("metaStore")
 	store, ok := s.(storage.MetaStore)
 	if !ok {
+		logger.Error("500 DELETE repository: no storage exists")
 		return errors.ErrNoStorage.WithDetail(nil)
 	}
-	vars := mux.Vars(r)
-	gun := vars["imageName"]
-	logger := ctxu.GetLoggerWithField(ctx, gun, "gun")
 	err := store.Delete(gun)
 	if err != nil {
 		logger.Error("500 DELETE repository")
@@ -175,16 +185,18 @@ func GetKeyHandler(ctx context.Context, w http.ResponseWriter, r *http.Request)
 
 func getKeyHandler(ctx context.Context, w http.ResponseWriter, r *http.Request, vars map[string]string) error {
 	gun, ok := vars["imageName"]
+	logger := ctxu.GetLoggerWithField(ctx, gun, "gun")
 	if !ok || gun == "" {
+		logger.Info("400 GET no gun in request")
 		return errors.ErrUnknown.WithDetail("no gun")
 	}
+
 	role, ok := vars["tufRole"]
 	if !ok || role == "" {
+		logger.Info("400 GET no role in request")
 		return errors.ErrUnknown.WithDetail("no role")
 	}
 
-	logger := ctxu.GetLoggerWithField(ctx, gun, "gun")
-
 	s := ctx.Value("metaStore")
 	store, ok := s.(storage.MetaStore)
 	if !ok || store == nil {
@@ -215,7 +227,7 @@ func getKeyHandler(ctx context.Context, w http.ResponseWriter, r *http.Request,
 	case data.CanonicalSnapshotRole:
 		key, err = snapshot.GetOrCreateSnapshotKey(gun, store, crypto, keyAlgorithm)
 	default:
-		logger.Errorf("400 GET %s key: %v", role, err)
+		logger.Infof("400 GET %s key: %v", role, err)
 		return errors.ErrInvalidRole.WithDetail(role)
 	}
 	if err != nil {

server/timestamp/timestamp.go

@@ -62,7 +62,7 @@ func GetOrCreateTimestamp(gun string, store storage.MetaStore, cryptoService sig
 
 	lastModified, timestampJSON, err := store.GetCurrent(gun, data.CanonicalTimestampRole)
 	if err != nil {
-		logrus.Error("error retrieving timestamp: ", err.Error())
+		logrus.Debug("error retrieving timestamp: ", err.Error())
 		return nil, nil, err
 	}
 

utils/http.go

@@ -5,7 +5,6 @@ import (
 	"net/http"
 	"time"
 
-	"github.com/Sirupsen/logrus"
 	ctxu "github.com/docker/distribution/context"
 	"github.com/docker/distribution/registry/api/errcode"
 	"github.com/docker/distribution/registry/auth"
@@ -79,9 +78,19 @@ func (root *rootHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		ctx = authCtx
 	}
 	if err := root.handler(ctx, w, r); err != nil {
+		if httpErr, ok := err.(errcode.ErrorCoder); ok {
+			// info level logging for non-5XX http errors
+			httpErrCode := httpErr.ErrorCode().Descriptor().HTTPStatusCode
+			if httpErrCode >= http.StatusInternalServerError {
+				// error level logging for 5XX http errors
+				log.Error(httpErr)
+			} else {
+				log.Info(httpErr)
+			}
+		}
 		e := errcode.ServeJSON(w, err)
 		if e != nil {
-			logrus.Error(e)
+			log.Error(e)
 		}
 		return
 	}