Address server errors received during layer upload

This changeset addresses intermittent internal server errors encountered during
pushes.  The root cause has been isolated to layers that result in identical,
empty filesystems but may have some path declarations (imaginge "./"),
resulting in different tarsums. The main error message reported during these
upload problems was a 500 error, which was not correct.  Further investigation
showed the errors to be rooted in digest verification when finishing uploads.

Inspection of the surrounding code also identified a few issues. PutLayerChunk
was slightly refactered into PutLayerUploadComplete. Helper methods were
avoided to make handler less confusing. This simplification leveraged an
earlier change in the spec that moved non-complete chunk uploads to the PATCH
method. Simple logging was also added in the unknown error case that should
help to avoid mysterious 500 errors in the future.

At the same time, the glaring omission of a proper layer upload cancel method
was rectified. This has been added in this change so it is not missed in the
future.

In the future, we may want to refactor the handler code to be more
straightforward, hopefully letting us avoid these problems in the future.

Added test cases that reproduce these errors and drove these changes include
the following:

1. Push a layer with an empty body results in invalid blob upload.
2. Push a layer with a different tarsum (in this case, empty tar)
3. Deleting a layer upload works.
4. Getting status on a deleted layer upload returns 404.

Common functionality was grouped into shared functions to remove repitition.
The API tests will still require future love.

Signed-off-by: Stephen J Day <stephen.day@docker.com>

registry/api_test.go

@@ -11,6 +11,7 @@ import (
 	"net/http/httputil"
 	"net/url"
 	"os"
+	"reflect"
 	"testing"
 
 	"github.com/docker/distribution/api/v2"
@@ -120,29 +121,59 @@ func TestLayerAPI(t *testing.T) {
 	checkResponse(t, "checking head on non-existent layer", resp, http.StatusNotFound)
 
 	// ------------------------------------------
-	// Upload a layer
+	// Start an upload and cancel
-	layerUploadURL, err := builder.BuildBlobUploadURL(imageName)
+	uploadURLBase := startPushLayer(t, builder, imageName)
+
+	req, err := http.NewRequest("DELETE", uploadURLBase, nil)
 	if err != nil {
-		t.Fatalf("error building upload url: %v", err)
+		t.Fatalf("unexpected error creating delete request: %v", err)
 	}
 
-	resp, err = http.Post(layerUploadURL, "", nil)
+	resp, err = http.DefaultClient.Do(req)
 	if err != nil {
-		t.Fatalf("error starting layer upload: %v", err)
+		t.Fatalf("unexpected error sending delete request: %v", err)
 	}
 
-	checkResponse(t, "starting layer upload", resp, http.StatusAccepted)
+	checkResponse(t, "deleting upload", resp, http.StatusNoContent)
-	checkHeaders(t, resp, http.Header{
-		"Location":       []string{"*"},
-		"Content-Length": []string{"0"},
-	})
 
+	// A status check should result in 404
+	resp, err = http.Get(uploadURLBase)
+	if err != nil {
+		t.Fatalf("unexpected error getting upload status: %v", err)
+	}
+	checkResponse(t, "status of deleted upload", resp, http.StatusNotFound)
+
+	// -----------------------------------------
+	// Do layer push with an empty body
+	uploadURLBase = startPushLayer(t, builder, imageName)
+	resp, err = doPushLayer(t, builder, imageName, layerDigest, uploadURLBase, bytes.NewReader([]byte{}))
+	if err != nil {
+		t.Fatalf("unexpected error doing bad layer push: %v", err)
+	}
+
+	checkResponse(t, "bad layer push", resp, http.StatusBadRequest)
+	checkBodyHasErrorCodes(t, "bad layer push", resp, v2.ErrorCodeBlobUploadInvalid)
+
+	// -----------------------------------------
+	// Do layer push with an invalid body
+
+	// This is a valid but empty tarfile!
+	badTar := bytes.Repeat([]byte("\x00"), 1024)
+	uploadURLBase = startPushLayer(t, builder, imageName)
+	resp, err = doPushLayer(t, builder, imageName, layerDigest, uploadURLBase, bytes.NewReader(badTar))
+	if err != nil {
+		t.Fatalf("unexpected error doing bad layer push: %v", err)
+	}
+
+	checkResponse(t, "bad layer push", resp, http.StatusBadRequest)
+	checkBodyHasErrorCodes(t, "bad layer push", resp, v2.ErrorCodeDigestInvalid)
+
+	// ------------------------------------------
+	// Now, actually do successful upload.
 	layerLength, _ := layerFile.Seek(0, os.SEEK_END)
 	layerFile.Seek(0, os.SEEK_SET)
 
-	// TODO(sday): Cancel the layer upload here and restart.
+	uploadURLBase = startPushLayer(t, builder, imageName)
-
-	uploadURLBase := startPushLayer(t, builder, imageName)
 	pushLayer(t, builder, imageName, layerDigest, uploadURLBase, layerFile)
 
 	// ------------------------
@@ -218,27 +249,7 @@ func TestManifestAPI(t *testing.T) {
 	defer resp.Body.Close()
 
 	checkResponse(t, "getting non-existent manifest", resp, http.StatusNotFound)
-
+	checkBodyHasErrorCodes(t, "getting non-existent manifest", resp, v2.ErrorCodeManifestUnknown)
-	// TODO(stevvooe): Shoot. The error setup is not working out. The content-
-	// type headers are being set after writing the status code.
-	// if resp.Header.Get("Content-Type") != "application/json; charset=utf-8" {
-	// 	t.Fatalf("unexpected content type: %v != 'application/json'",
-	// 		resp.Header.Get("Content-Type"))
-	// }
-	dec := json.NewDecoder(resp.Body)
-
-	var respErrs v2.Errors
-	if err := dec.Decode(&respErrs); err != nil {
-		t.Fatalf("unexpected error decoding error response: %v", err)
-	}
-
-	if len(respErrs.Errors) == 0 {
-		t.Fatalf("expected errors in response")
-	}
-
-	if respErrs.Errors[0].Code != v2.ErrorCodeManifestUnknown {
-		t.Fatalf("expected manifest unknown error: got %v", respErrs)
-	}
 
 	tagsURL, err := builder.BuildTagsURL(imageName)
 	if err != nil {
@@ -253,18 +264,7 @@ func TestManifestAPI(t *testing.T) {
 
 	// Check that we get an unknown repository error when asking for tags
 	checkResponse(t, "getting unknown manifest tags", resp, http.StatusNotFound)
-	dec = json.NewDecoder(resp.Body)
+	checkBodyHasErrorCodes(t, "getting unknown manifest tags", resp, v2.ErrorCodeNameUnknown)
-	if err := dec.Decode(&respErrs); err != nil {
-		t.Fatalf("unexpected error decoding error response: %v", err)
-	}
-
-	if len(respErrs.Errors) == 0 {
-		t.Fatalf("expected errors in response")
-	}
-
-	if respErrs.Errors[0].Code != v2.ErrorCodeNameUnknown {
-		t.Fatalf("expected respository unknown error: got %v", respErrs)
-	}
 
 	// --------------------------------
 	// Attempt to push unsigned manifest with missing layers
@@ -284,41 +284,17 @@ func TestManifestAPI(t *testing.T) {
 	resp = putManifest(t, "putting unsigned manifest", manifestURL, unsignedManifest)
 	defer resp.Body.Close()
 	checkResponse(t, "posting unsigned manifest", resp, http.StatusBadRequest)
+	_, p, counts := checkBodyHasErrorCodes(t, "getting unknown manifest tags", resp,
+		v2.ErrorCodeManifestUnverified, v2.ErrorCodeBlobUnknown, v2.ErrorCodeDigestInvalid)
 
-	dec = json.NewDecoder(resp.Body)
+	expectedCounts := map[v2.ErrorCode]int{
-	if err := dec.Decode(&respErrs); err != nil {
+		v2.ErrorCodeManifestUnverified: 1,
-		t.Fatalf("unexpected error decoding error response: %v", err)
+		v2.ErrorCodeBlobUnknown:        2,
+		v2.ErrorCodeDigestInvalid:      2,
 	}
 
-	var unverified int
+	if !reflect.DeepEqual(counts, expectedCounts) {
-	var missingLayers int
+		t.Fatalf("unexpected number of error codes encountered: %v\n!=\n%v\n---\n%s", counts, expectedCounts, string(p))
-	var invalidDigests int
-
-	for _, err := range respErrs.Errors {
-		switch err.Code {
-		case v2.ErrorCodeManifestUnverified:
-			unverified++
-		case v2.ErrorCodeBlobUnknown:
-			missingLayers++
-		case v2.ErrorCodeDigestInvalid:
-			// TODO(stevvooe): This error isn't quite descriptive enough --
-			// the layer with an invalid digest isn't identified.
-			invalidDigests++
-		default:
-			t.Fatalf("unexpected error: %v", err)
-		}
-	}
-
-	if unverified != 1 {
-		t.Fatalf("should have received one unverified manifest error: %v", respErrs)
-	}
-
-	if missingLayers != 2 {
-		t.Fatalf("should have received two missing layer errors: %v", respErrs)
-	}
-
-	if invalidDigests != 2 {
-		t.Fatalf("should have received two invalid digest errors: %v", respErrs)
 	}
 
 	// TODO(stevvooe): Add a test case where we take a mostly valid registry,
@@ -363,7 +339,7 @@ func TestManifestAPI(t *testing.T) {
 	checkResponse(t, "fetching uploaded manifest", resp, http.StatusOK)
 
 	var fetchedManifest manifest.SignedManifest
-	dec = json.NewDecoder(resp.Body)
+	dec := json.NewDecoder(resp.Body)
 	if err := dec.Decode(&fetchedManifest); err != nil {
 		t.Fatalf("error decoding fetched manifest: %v", err)
 	}
@@ -448,11 +424,9 @@ func startPushLayer(t *testing.T, ub *v2.URLBuilder, name string) string {
 	return resp.Header.Get("Location")
 }
 
-// pushLayer pushes the layer content returning the url on success.
+// doPushLayer pushes the layer content returning the url on success returning
-func pushLayer(t *testing.T, ub *v2.URLBuilder, name string, dgst digest.Digest, uploadURLBase string, rs io.ReadSeeker) string {
+// the response. If you're only expecting a successful response, use pushLayer.
-	rsLength, _ := rs.Seek(0, os.SEEK_END)
+func doPushLayer(t *testing.T, ub *v2.URLBuilder, name string, dgst digest.Digest, uploadURLBase string, body io.Reader) (*http.Response, error) {
-	rs.Seek(0, os.SEEK_SET)
-
 	u, err := url.Parse(uploadURLBase)
 	if err != nil {
 		t.Fatalf("unexpected error parsing pushLayer url: %v", err)
@@ -462,23 +436,24 @@ func pushLayer(t *testing.T, ub *v2.URLBuilder, name string, dgst digest.Digest,
 		"_state": u.Query()["_state"],
 
 		"digest": []string{dgst.String()},
-
-		// TODO(stevvooe): Layer upload can be completed with and without size
-		// argument. We'll need to add a test that checks the latter path.
-		"size": []string{fmt.Sprint(rsLength)},
 	}.Encode()
 
 	uploadURL := u.String()
 
 	// Just do a monolithic upload
-	req, err := http.NewRequest("PUT", uploadURL, rs)
+	req, err := http.NewRequest("PUT", uploadURL, body)
 	if err != nil {
 		t.Fatalf("unexpected error creating new request: %v", err)
 	}
 
-	resp, err := http.DefaultClient.Do(req)
+	return http.DefaultClient.Do(req)
+}
+
+// pushLayer pushes the layer content returning the url on success.
+func pushLayer(t *testing.T, ub *v2.URLBuilder, name string, dgst digest.Digest, uploadURLBase string, body io.Reader) string {
+	resp, err := doPushLayer(t, ub, name, dgst, uploadURLBase, body)
 	if err != nil {
-		t.Fatalf("unexpected error doing put: %v", err)
+		t.Fatalf("unexpected error doing push layer request: %v", err)
 	}
 	defer resp.Body.Close()
 
@@ -506,6 +481,57 @@ func checkResponse(t *testing.T, msg string, resp *http.Response, expectedStatus
 	}
 }
 
+// checkBodyHasErrorCodes ensures the body is an error body and has the
+// expected error codes, returning the error structure, the json slice and a
+// count of the errors by code.
+func checkBodyHasErrorCodes(t *testing.T, msg string, resp *http.Response, errorCodes ...v2.ErrorCode) (v2.Errors, []byte, map[v2.ErrorCode]int) {
+	p, err := ioutil.ReadAll(resp.Body)
+	if err != nil {
+		t.Fatalf("unexpected error reading body %s: %v", msg, err)
+	}
+
+	var errs v2.Errors
+	if err := json.Unmarshal(p, &errs); err != nil {
+		t.Fatalf("unexpected error decoding error response: %v", err)
+	}
+
+	if len(errs.Errors) == 0 {
+		t.Fatalf("expected errors in response")
+	}
+
+	// TODO(stevvooe): Shoot. The error setup is not working out. The content-
+	// type headers are being set after writing the status code.
+	// if resp.Header.Get("Content-Type") != "application/json; charset=utf-8" {
+	// 	t.Fatalf("unexpected content type: %v != 'application/json'",
+	// 		resp.Header.Get("Content-Type"))
+	// }
+
+	expected := map[v2.ErrorCode]struct{}{}
+	counts := map[v2.ErrorCode]int{}
+
+	// Initialize map with zeros for expected
+	for _, code := range errorCodes {
+		expected[code] = struct{}{}
+		counts[code] = 0
+	}
+
+	for _, err := range errs.Errors {
+		if _, ok := expected[err.Code]; !ok {
+			t.Fatalf("unexpected error code %v encountered: %s ", err.Code, string(p))
+		}
+		counts[err.Code]++
+	}
+
+	// Ensure that counts of expected errors were all non-zero
+	for code := range expected {
+		if counts[code] == 0 {
+			t.Fatalf("expected error code %v not encounterd: %s", code, string(p))
+		}
+	}
+
+	return errs, p, counts
+}
+
 func maybeDumpResponse(t *testing.T, resp *http.Response) {
 	if d, err := httputil.DumpResponse(resp, true); err != nil {
 		t.Logf("error dumping response: %v", err)

registry/layerupload.go

@@ -23,10 +23,12 @@ func layerUploadDispatcher(ctx *Context, r *http.Request) http.Handler {
 	}
 
 	handler := http.Handler(handlers.MethodHandler{
-		"POST":   http.HandlerFunc(luh.StartLayerUpload),
+		"POST": http.HandlerFunc(luh.StartLayerUpload),
-		"GET":    http.HandlerFunc(luh.GetUploadStatus),
+		"GET":  http.HandlerFunc(luh.GetUploadStatus),
-		"HEAD":   http.HandlerFunc(luh.GetUploadStatus),
+		"HEAD": http.HandlerFunc(luh.GetUploadStatus),
-		"PUT":    http.HandlerFunc(luh.PutLayerChunk),
+		// TODO(stevvooe): Must implement patch support.
+		// "PATCH":    http.HandlerFunc(luh.PutLayerChunk),
+		"PUT":    http.HandlerFunc(luh.PutLayerUploadComplete),
 		"DELETE": http.HandlerFunc(luh.CancelLayerUpload),
 	})
 
@@ -158,55 +160,80 @@ func (luh *layerUploadHandler) GetUploadStatus(w http.ResponseWriter, r *http.Re
 	w.WriteHeader(http.StatusNoContent)
 }
 
-// PutLayerChunk receives a layer chunk during the layer upload process,
+// PutLayerUploadComplete takes the final request of a layer upload. The final
-// possible completing the upload with a checksum and length.
+// chunk may include all the layer data, the final chunk of layer data or no
-func (luh *layerUploadHandler) PutLayerChunk(w http.ResponseWriter, r *http.Request) {
+// layer data. Any data provided is received and verified. If successful, the
+// layer is linked into the blob store and 201 Created is returned with the
+// canonical url of the layer.
+func (luh *layerUploadHandler) PutLayerUploadComplete(w http.ResponseWriter, r *http.Request) {
 	if luh.Upload == nil {
 		w.WriteHeader(http.StatusNotFound)
 		luh.Errors.Push(v2.ErrorCodeBlobUploadUnknown)
-	}
-
-	var finished bool
-
-	// TODO(stevvooe): This is woefully incomplete. Missing stuff:
-	//
-	// 1. Extract information from range header, if present.
-	// 2. Check offset of current layer.
-	// 3. Emit correct error responses.
-
-	// Read in the chunk
-	io.Copy(luh.Upload, r.Body)
-
-	if err := luh.maybeCompleteUpload(w, r); err != nil {
-		if err != errNotReadyToComplete {
-			switch err := err.(type) {
-			case storage.ErrLayerInvalidSize:
-				w.WriteHeader(http.StatusBadRequest)
-				luh.Errors.Push(v2.ErrorCodeSizeInvalid, err)
-				return
-			case storage.ErrLayerInvalidDigest:
-				w.WriteHeader(http.StatusBadRequest)
-				luh.Errors.Push(v2.ErrorCodeDigestInvalid, err)
-				return
-			default:
-				w.WriteHeader(http.StatusInternalServerError)
-				luh.Errors.Push(v2.ErrorCodeUnknown, err)
-				return
-			}
-		}
-	}
-
-	if err := luh.layerUploadResponse(w, r); err != nil {
-		w.WriteHeader(http.StatusInternalServerError) // Error conditions here?
-		luh.Errors.Push(v2.ErrorCodeUnknown, err)
 		return
 	}
 
-	if finished {
+	dgstStr := r.FormValue("digest") // TODO(stevvooe): Support multiple digest parameters!
-		w.WriteHeader(http.StatusCreated)
+
-	} else {
+	if dgstStr == "" {
-		w.WriteHeader(http.StatusAccepted)
+		// no digest? return error, but allow retry.
+		w.WriteHeader(http.StatusNotFound)
+		luh.Errors.Push(v2.ErrorCodeDigestInvalid, "digest missing")
+		return
 	}
+
+	dgst, err := digest.ParseDigest(dgstStr)
+	if err != nil {
+		// no digest? return error, but allow retry.
+		w.WriteHeader(http.StatusNotFound)
+		luh.Errors.Push(v2.ErrorCodeDigestInvalid, "digest parsing failed")
+		return
+	}
+
+	// TODO(stevvooe): Check the incoming range header here, per the
+	// specification. LayerUpload should be seeked (sought?) to that position.
+
+	// Read in the final chunk, if any.
+	io.Copy(luh.Upload, r.Body)
+
+	layer, err := luh.Upload.Finish(dgst)
+	if err != nil {
+		switch err := err.(type) {
+		case storage.ErrLayerUploadUnavailable:
+			w.WriteHeader(http.StatusBadRequest)
+			// TODO(stevvooe): Arguably, we may want to add an error code to
+			// cover this condition. It is not always a client error but it
+			// may be. For now, we effectively throw out the upload and have
+			// them start over.
+			luh.Errors.Push(v2.ErrorCodeBlobUploadInvalid, err.Err)
+		case storage.ErrLayerInvalidDigest:
+			w.WriteHeader(http.StatusBadRequest)
+			luh.Errors.Push(v2.ErrorCodeDigestInvalid, err)
+		default:
+			luh.log.Errorf("unknown error completing upload: %#v", err)
+			w.WriteHeader(http.StatusInternalServerError)
+			luh.Errors.Push(v2.ErrorCodeUnknown, err)
+		}
+
+		// Clean up the backend layer data if there was an error.
+		if err := luh.Upload.Cancel(); err != nil {
+			// If the cleanup fails, all we can do is observe and report.
+			luh.log.Errorf("error canceling upload after error: %v", err)
+		}
+
+		return
+	}
+
+	// Build our canonical layer url
+	layerURL, err := luh.urlBuilder.BuildBlobURL(layer.Name(), layer.Digest())
+	if err != nil {
+		luh.Errors.Push(v2.ErrorCodeUnknown, err)
+		w.WriteHeader(http.StatusInternalServerError)
+		return
+	}
+
+	w.Header().Set("Location", layerURL)
+	w.Header().Set("Content-Length", "0")
+	w.WriteHeader(http.StatusCreated)
 }
 
 // CancelLayerUpload cancels an in-progress upload of a layer.
@@ -214,8 +241,16 @@ func (luh *layerUploadHandler) CancelLayerUpload(w http.ResponseWriter, r *http.
 	if luh.Upload == nil {
 		w.WriteHeader(http.StatusNotFound)
 		luh.Errors.Push(v2.ErrorCodeBlobUploadUnknown)
+		return
 	}
 
+	if err := luh.Upload.Cancel(); err != nil {
+		luh.log.Errorf("error encountered canceling upload: %v", err)
+		w.WriteHeader(http.StatusInternalServerError)
+		luh.Errors.PushErr(err)
+	}
+
+	w.WriteHeader(http.StatusNoContent)
 }
 
 // layerUploadResponse provides a standard request for uploading layers and
@@ -257,45 +292,3 @@ func (luh *layerUploadHandler) layerUploadResponse(w http.ResponseWriter, r *htt
 
 	return nil
 }
-
-var errNotReadyToComplete = fmt.Errorf("not ready to complete upload")
-
-// maybeCompleteUpload tries to complete the upload if the correct parameters
-// are available. Returns errNotReadyToComplete if not ready to complete.
-func (luh *layerUploadHandler) maybeCompleteUpload(w http.ResponseWriter, r *http.Request) error {
-	// If we get a digest and length, we can finish the upload.
-	dgstStr := r.FormValue("digest") // TODO(stevvooe): Support multiple digest parameters!
-
-	if dgstStr == "" {
-		return errNotReadyToComplete
-	}
-
-	dgst, err := digest.ParseDigest(dgstStr)
-	if err != nil {
-		return err
-	}
-
-	luh.completeUpload(w, r, dgst)
-	return nil
-}
-
-// completeUpload finishes out the upload with the correct response.
-func (luh *layerUploadHandler) completeUpload(w http.ResponseWriter, r *http.Request, dgst digest.Digest) {
-	layer, err := luh.Upload.Finish(dgst)
-	if err != nil {
-		luh.Errors.Push(v2.ErrorCodeUnknown, err)
-		w.WriteHeader(http.StatusInternalServerError)
-		return
-	}
-
-	layerURL, err := luh.urlBuilder.BuildBlobURL(layer.Name(), layer.Digest())
-	if err != nil {
-		luh.Errors.Push(v2.ErrorCodeUnknown, err)
-		w.WriteHeader(http.StatusInternalServerError)
-		return
-	}
-
-	w.Header().Set("Location", layerURL)
-	w.Header().Set("Content-Length", "0")
-	w.WriteHeader(http.StatusCreated)
-}