Merge pull request #12 from Azure/dev/deeptivai/trackDownloadInfoRC

Track Request ID, Response ID, and Response Code + Add response-code-specific error messages

pkg/download/blob.go

@@ -11,6 +11,7 @@ import (
 
 	"github.com/Azure/azure-sdk-for-go/storage"
 	"github.com/Azure/run-command-handler-linux/pkg/blobutil"
+	"github.com/google/uuid"
 	"github.com/pkg/errors"
 )
 
@@ -30,7 +31,11 @@ func (b blobDownload) GetRequest() (*http.Request, error) {
 	if err != nil {
 		return nil, err
 	}
-	return http.NewRequest("GET", url, nil)
+	req, err := http.NewRequest("GET", url, nil)
+	if req != nil {
+		req.Header.Set(xMsClientRequestIdHeaderName, uuid.New().String())
+	}
+	return req, err
 }
 
 // getURL returns publicly downloadable URL of the Azure Blob

pkg/download/blob_test.go

@@ -11,9 +11,15 @@ import (
 
 	"github.com/Azure/azure-sdk-for-go/storage"
 	"github.com/Azure/run-command-handler-linux/pkg/blobutil"
+	"github.com/go-kit/kit/log"
+	"github.com/google/uuid"
 	"github.com/stretchr/testify/require"
 )
 
+var (
+	testctx = log.NewContext(log.NewNopLogger())
+)
+
 func Test_blobDownload_validateInputs(t *testing.T) {
 	type sas interface {
 		getURL() (string, error)
@@ -72,12 +78,29 @@ func Test_blobDownload_fails_badCreds(t *testing.T) {
 		Container:   "foocontainer",
 	})
 
-	status, _, err := Download(d)
+	status, _, err := Download(testctx, d)
 	require.NotNil(t, err)
-	require.Contains(t, err.Error(), "Status code 403 while downloading blob")
+	require.Contains(t, err.Error(), "Please verify the machine has network connectivity")
+	require.Contains(t, err.Error(), "403")
 	require.Equal(t, status, http.StatusForbidden)
 }
 
+// Tests that a common error message will be uniquely formatted
+func Test_blobDownload_fails_badRequest(t *testing.T) {
+	d := badRequestBlobDownload{
+		blobDownload{"example", "Zm9vCg==", blobutil.AzureBlobRef{
+			StorageBase: storage.DefaultBaseURL,
+			Blob:        "fooBlob.txt",
+			Container:   "foocontainer",
+		}}}
+
+	status, _, err := Download(testctx, d)
+	require.NotNil(t, err)
+	require.Contains(t, err.Error(), "parts of the request were incorrectly formatted, missing, and/or invalid")
+	require.Contains(t, err.Error(), "400")
+	require.Equal(t, status, http.StatusBadRequest)
+}
+
 func Test_blobDownload_fails_urlNotFound(t *testing.T) {
 	d := NewBlobDownload("accountname", "Zm9vCg==", blobutil.AzureBlobRef{
 		StorageBase: ".example.com",
@@ -85,7 +108,7 @@ func Test_blobDownload_fails_urlNotFound(t *testing.T) {
 		Container:   "foocontainer",
 	})
 
-	_, _, err := Download(d)
+	_, _, err := Download(testctx, d)
 	require.NotNil(t, err)
 	require.Contains(t, err.Error(), "http request failed:")
 }
@@ -145,7 +168,7 @@ func Test_blobDownload_actualBlob(t *testing.T) {
 		Blob:        name,
 		StorageBase: base,
 	})
-	_, body, err := Download(d)
+	_, body, err := Download(testctx, d)
 	require.Nil(t, err)
 	defer body.Close()
 	b, err := ioutil.ReadAll(body)
@@ -172,3 +195,20 @@ func Test_blobAppend_actualBlob(t *testing.T) {
 	err = blobref.AppendBlock([]byte("Third line\n"), nil)
 	require.Nil(t, err)
 }
+
+type badRequestBlobDownload struct {
+	blobDownloader blobDownload
+}
+
+func (b badRequestBlobDownload) GetRequest() (*http.Request, error) {
+	url, err := b.blobDownloader.getURL()
+	if err != nil {
+		return nil, err
+	}
+	req, error := http.NewRequest("GET", url, nil)
+	if req != nil {
+		req.Header.Set(xMsClientRequestIdHeaderName, uuid.New().String())
+		req.Header.Set("x-ms-version", "bad value")
+	}
+	return req, error
+}

pkg/download/blobwithmsitoken.go

@@ -8,6 +8,7 @@ import (
 
 	"github.com/Azure/azure-extension-foundation/httputil"
 	"github.com/Azure/azure-extension-foundation/msi"
+	"github.com/google/uuid"
 	"github.com/pkg/errors"
 )
 
@@ -55,6 +56,7 @@ func (self *blobWithMsiToken) GetRequest() (*http.Request, error) {
 		return nil, err
 	}
 
+	request.Header.Set(xMsClientRequestIdHeaderName, uuid.New().String())
 	if IsAzureStorageBlobUri(self.url) {
 		request.Header.Set("Authorization", fmt.Sprintf("Bearer %s", msi.AccessToken))
 		request.Header.Set(xMsVersionHeaderName, xMsVersionValue)

pkg/download/blobwithmsitoken_test.go

@@ -3,6 +3,7 @@ package download
 import (
 	"encoding/json"
 	"io/ioutil"
+	// "net/http"
 	"testing"
 
 	"github.com/Azure/azure-extension-foundation/msi"
@@ -33,8 +34,8 @@ var msiJson = `` // place the msi json here e.g.
 // the second command gets user assigned identity with its client id
 // the third command gets user assigned identity with its object id
 
-var blobUri = ""         // set the blob to download here e.g. https://storageaccount.blob.core.windows.net/container/blobname
-var stringToLookFor = "" // the string to look for in you blob
+var blobUri = "https://deeptivaistorage.blob.core.windows.net/newcontainer/errors.txt" // set the blob to download here e.g. https://storageaccount.blob.core.windows.net/container/blobname
+var stringToLookFor = "hello"                                                          // the string to look for in you blob
 
 func Test_realDownloadBlobWithMsiToken(t *testing.T) {
 	if msiJson == "" || blobUri == "" || stringToLookFor == "" {
@@ -45,7 +46,7 @@ func Test_realDownloadBlobWithMsiToken(t *testing.T) {
 		err := json.Unmarshal([]byte(msiJson), &msi)
 		return msi, err
 	}}
-	_, stream, err := Download(&downloader)
+	_, stream, err := Download(testctx, &downloader)
 	require.NoError(t, err, "File download failed")
 	defer stream.Close()
 

pkg/download/downloader.go

@@ -8,6 +8,7 @@ import (
 	"time"
 
 	"github.com/Azure/run-command-handler-linux/pkg/urlutil"
+	"github.com/go-kit/kit/log"
 	"github.com/pkg/errors"
 )
 
@@ -45,11 +46,15 @@ var (
 // Download retrieves a response body and checks the response status code to see
 // if it is 200 OK and then returns the response body. It issues a new request
 // every time called. It is caller's responsibility to close the response body.
-func Download(downloader Downloader) (int, io.ReadCloser, error) {
+func Download(ctx *log.Context, downloader Downloader) (int, io.ReadCloser, error) {
 	request, err := downloader.GetRequest()
 	if err != nil {
 		return -1, nil, errors.Wrapf(err, "failed to create http request")
 	}
+	requestID := request.Header.Get(xMsClientRequestIdHeaderName)
+	if len(requestID) > 0 {
+		ctx.Log("info", fmt.Sprintf("starting download with client request ID %s", requestID))
+	}
 
 	response, err := httpClient.Do(request)
 	if err != nil {
@@ -61,20 +66,53 @@ func Download(downloader Downloader) (int, io.ReadCloser, error) {
 		return response.StatusCode, response.Body, nil
 	}
 
-	err = fmt.Errorf("Status code %d while downloading blob '%s'. Use either a public script URI that points to .sh file, Azure storage blob SAS URI or storage blob accessible by a managed identity and retry. For more info, refer https://aka.ms/RunCommandManagedLinux", response.StatusCode, request.URL.Opaque)
+	errString := fmt.Sprintf("Status code %d while downloading blob '%s'. Use either a public script URI that points to .sh file, Azure storage blob SAS URI or storage blob accessible by a managed identity and retry. For more information, see https://aka.ms/RunCommandManagedLinux", response.StatusCode, request.URL.Opaque)
+	requestId := response.Header.Get(xMsServiceRequestIdHeaderName)
 	switch downloader.(type) {
 	case *blobWithMsiToken:
 		switch response.StatusCode {
 		case http.StatusNotFound:
-			notFoundError := fmt.Errorf("Make sure Azure blob '%s' and managed identity exist, and identity has been given access to storage blob's container with 'Storage Blob Data Reader' role assignment. In case of user assigned identity, make sure you add it under VM's identity. For more info, refer https://aka.ms/RunCommandManagedLinux", request.URL.Opaque)
-			return response.StatusCode, nil, errors.Wrapf(notFoundError, MsiDownload404ErrorString)
-		case http.StatusForbidden:
+			notFoundError := fmt.Sprintf("RunCommand failed to download the blob '%s' and received a response code '%s'. Make sure that the Azure blob and managed identity exist, and the identity has access to the storage blob's container with the 'Storage Blob Data Reader' role assignment. For a user-assigned identity, add it under the VM's identity. For more information, see https://aka.ms/RunCommandManagedLinux", request.URL.Opaque, response.Status)
+			errString = fmt.Sprintf("%s: %s", MsiDownload404ErrorString, notFoundError)
+		case http.StatusForbidden,
+			http.StatusUnauthorized,
+			http.StatusBadRequest,
+			http.StatusConflict:
+			forbiddenError := fmt.Sprintf("RunCommand failed to download the blob '%s' and received a response code '%s'. Ensure that the managed identity has access to the storage blob's container with the 'Storage Blob Data Reader' role assignment. For a user-assigned identity, add it under the VM's identity. For more information, see https://aka.ms/RunCommandManagedLinux", request.URL.Opaque, response.Status)
+			errString = fmt.Sprintf("%s: %s", MsiDownload403ErrorString, forbiddenError)
+		}
+		break
+	default:
+		hostname := request.URL.Host
+		switch response.StatusCode {
 		case http.StatusUnauthorized:
+			errString = fmt.Sprintf("RunCommand failed to download the file from %s because access was denied. Please fix the blob permissions and try again. The response code and message returned were: %q.",
+				hostname,
+				response.Status)
+			break
+		case http.StatusNotFound:
+			errString = fmt.Sprintf("RunCommand failed to download the file from %s because it does not exist. Please create the blob and try again, the response code and message returned were: %q",
+				hostname,
+				response.Status)
+
 		case http.StatusBadRequest:
-		case http.StatusConflict:
-			forbiddenError := fmt.Errorf("Make sure managed identity has been given access to container of storage blob '%s' with 'Storage Blob Data Reader' role assignment. In case of user assigned identity, make sure you add it under VM's identity. For more info, refer https://aka.ms/RunCommandManagedLinux", request.URL.Opaque)
-			return response.StatusCode, nil, errors.Wrapf(forbiddenError, MsiDownload403ErrorString)
+			errString = fmt.Sprintf("RunCommand failed to download the file from %s because parts of the request were incorrectly formatted, missing, and/or invalid. The response code and message returned were: %q",
+				hostname,
+				response.Status)
+
+		case http.StatusInternalServerError:
+			errString = fmt.Sprintf("RunCommand failed to download the file from %s due to an issue with storage. The response code and message returned were: %q",
+				hostname,
+				response.Status)
+		default:
+			errString = fmt.Sprintf("RunCommand failed to download the file from %s because the server returned a response code and message of %q Please verify the machine has network connectivity.",
+				hostname,
+				response.Status)
 		}
 	}
-	return response.StatusCode, nil, err
+
+	if len(requestId) > 0 {
+		errString += fmt.Sprintf(" (Service request ID: %s)", requestId)
+	}
+	return response.StatusCode, nil, fmt.Errorf(errString)
 }

pkg/download/downloader_test.go

@@ -10,32 +10,36 @@ import (
 	"testing"
 
 	"github.com/Azure/azure-extension-foundation/msi"
-
 	"github.com/Azure/run-command-handler-linux/pkg/download"
 	"github.com/ahmetalpbalkan/go-httpbin"
+	"github.com/go-kit/kit/log"
 	"github.com/stretchr/testify/require"
 )
 
 type badDownloader struct{ calls int }
 
+var (
+	testctx = log.NewContext(log.NewNopLogger())
+)
+
 func (b *badDownloader) GetRequest() (*http.Request, error) {
 	b.calls++
 	return nil, errors.New("expected error")
 }
 
 func TestDownload_wrapsGetRequestError(t *testing.T) {
-	_, _, err := download.Download(new(badDownloader))
+	_, _, err := download.Download(testctx, new(badDownloader))
 	require.NotNil(t, err)
 	require.EqualError(t, err, "failed to create http request: expected error")
 }
 
 func TestDownload_wrapsHTTPError(t *testing.T) {
-	_, _, err := download.Download(download.NewURLDownload("bad url"))
+	_, _, err := download.Download(testctx, download.NewURLDownload("bad url"))
 	require.NotNil(t, err)
 	require.Contains(t, err.Error(), "http request failed:")
 }
 
-func TestDownload_badStatusCodeFails(t *testing.T) {
+func TestDownload_wrapsCommonErrorCodes(t *testing.T) {
 	srv := httptest.NewServer(httpbin.GetMux())
 	defer srv.Close()
 
@@ -47,9 +51,21 @@ func TestDownload_badStatusCodeFails(t *testing.T) {
 		http.StatusBadRequest,
 		http.StatusUnauthorized,
 	} {
-		_, _, err := download.Download(download.NewURLDownload(fmt.Sprintf("%s/status/%d", srv.URL, code)))
+		respCode, _, err := download.Download(testctx, download.NewURLDownload(fmt.Sprintf("%s/status/%d", srv.URL, code)))
 		require.NotNil(t, err, "not failed for code:%d", code)
-		require.Contains(t, err.Error(), fmt.Sprintf("Status code %d while downloading blob", code))
+		require.Equal(t, code, respCode)
+		switch respCode {
+		case http.StatusNotFound:
+			require.Contains(t, err.Error(), "because it does not exist")
+		case http.StatusForbidden:
+			require.Contains(t, err.Error(), "Please verify the machine has network connectivity")
+		case http.StatusInternalServerError:
+			require.Contains(t, err.Error(), "due to an issue with storage")
+		case http.StatusBadRequest:
+			require.Contains(t, err.Error(), "because parts of the request were incorrectly formatted, missing, and/or invalid")
+		case http.StatusUnauthorized:
+			require.Contains(t, err.Error(), "because access was denied")
+		}
 	}
 }
 
@@ -57,7 +73,7 @@ func TestDownload_statusOKSucceeds(t *testing.T) {
 	srv := httptest.NewServer(httpbin.GetMux())
 	defer srv.Close()
 
-	_, body, err := download.Download(download.NewURLDownload(srv.URL + "/status/200"))
+	_, body, err := download.Download(testctx, download.NewURLDownload(srv.URL+"/status/200"))
 	require.Nil(t, err)
 	defer body.Close()
 	require.NotNil(t, body)
@@ -72,24 +88,35 @@ func TestDowload_msiDownloaderErrorMessage(t *testing.T) {
 
 	msiDownloader404 := download.NewBlobWithMsiDownload(srv.URL+"/status/404", mockMsiProvider)
 
-	returnCode, body, err := download.Download(msiDownloader404)
+	returnCode, body, err := download.Download(testctx, msiDownloader404)
 	require.True(t, strings.Contains(err.Error(), download.MsiDownload404ErrorString), "error string doesn't contain the correct message")
+	require.Contains(t, err.Error(), "For more information, see https://aka.ms/RunCommandManagedLinux", "error string doesn't contain full message")
 	require.Nil(t, body, "body is not nil for failed download")
 	require.Equal(t, 404, returnCode, "return code was not 404")
 
 	msiDownloader403 := download.NewBlobWithMsiDownload(srv.URL+"/status/403", mockMsiProvider)
-	returnCode, body, err = download.Download(msiDownloader403)
+	returnCode, body, err = download.Download(testctx, msiDownloader403)
 	require.True(t, strings.Contains(err.Error(), download.MsiDownload403ErrorString), "error string doesn't contain the correct message")
+	require.Contains(t, err.Error(), "For more information, see https://aka.ms/RunCommandManagedLinux", "error string doesn't contain full message")
 	require.Nil(t, body, "body is not nil for failed download")
 	require.Equal(t, 403, returnCode, "return code was not 403")
 
+	// Should use default error message for any error code other than 400, 401, 403, 404, and 409
+	msiDownloader500 := download.NewBlobWithMsiDownload(srv.URL+"/status/500", mockMsiProvider)
+	returnCode, body, err = download.Download(testctx, msiDownloader500)
+	fmt.Println(err.Error())
+	require.Contains(t, err.Error(), "Use either a public script URI that points to .sh file", "error string doesn't contain full message")
+	require.Contains(t, err.Error(), "For more information, see https://aka.ms/RunCommandManagedLinux", "error string doesn't contain full message")
+	require.Nil(t, body, "body is not nil for failed download")
+	require.Equal(t, 500, returnCode, "return code was not 500")
+
 }
 
 func TestDownload_retrievesBody(t *testing.T) {
 	srv := httptest.NewServer(httpbin.GetMux())
 	defer srv.Close()
 
-	_, body, err := download.Download(download.NewURLDownload(srv.URL + "/bytes/65536"))
+	_, body, err := download.Download(testctx, download.NewURLDownload(srv.URL+"/bytes/65536"))
 	require.Nil(t, err)
 	defer body.Close()
 	b, err := ioutil.ReadAll(body)
@@ -101,7 +128,7 @@ func TestDownload_bodyClosesWithoutError(t *testing.T) {
 	srv := httptest.NewServer(httpbin.GetMux())
 	defer srv.Close()
 
-	_, body, err := download.Download(download.NewURLDownload(srv.URL + "/get"))
+	_, body, err := download.Download(testctx, download.NewURLDownload(srv.URL+"/get"))
 	require.Nil(t, err)
 	require.Nil(t, body.Close(), "body should close fine")
 }

pkg/download/retry.go

@@ -37,7 +37,7 @@ func WithRetries(ctx *log.Context, downloaders []Downloader, sf SleepFunc) (io.R
 	for _, d := range downloaders {
 		for n := 0; n < expRetryN; n++ {
 			ctx := ctx.With("retry", n)
-			status, out, err := Download(d)
+			status, out, err := Download(ctx, d)
 			if err == nil {
 				return out, nil
 			}

pkg/download/retry_test.go

@@ -60,7 +60,8 @@ func TestWithRetries_failingBadStatusCode_validateSleeps(t *testing.T) {
 
 	sr := new(sleepRecorder)
 	_, err := download.WithRetries(nopLog(), []download.Downloader{d}, sr.Sleep)
-	require.Contains(t, err.Error(), "Status code 429 while downloading blob")
+	require.Contains(t, err.Error(), "429 Too Many Requests")
+	require.Contains(t, err.Error(), "Please verify the machine has network connectivity")
 
 	require.Equal(t, sleepSchedule, []time.Duration(*sr))
 }
@@ -98,15 +99,15 @@ func TestRetriesWith_SwitchDownloaderThenFailWithCorrectErrorMessage(t *testing.
 		return msi.Msi{AccessToken: "fakeAccessToken"}, nil
 	}
 
-	d404 := mockDownloader{0, svr.URL + "/status/404"}
+	d403 := mockDownloader{0, svr.URL + "/status/403"}
 	msiDownloader403 := download.NewBlobWithMsiDownload(svr.URL+"/status/403", mockMsiProvider)
-	resp, err := download.WithRetries(nopLog(), []download.Downloader{&d404, msiDownloader403}, func(d time.Duration) { return })
+	resp, err := download.WithRetries(nopLog(), []download.Downloader{&d403, msiDownloader403}, func(d time.Duration) { return })
 	require.NotNil(t, err, "download with retries should fail")
 	require.Nil(t, resp, "response body should be nil for failed download with retries")
-	require.Equal(t, d404.timesCalled, 1)
-	require.Contains(t, err.Error(), "Status code 403 while downloading blob")
+	require.Equal(t, d403.timesCalled, 1)
+	require.Contains(t, err.Error(), "403 Forbidden")
 
-	d404 = mockDownloader{0, svr.URL + "/status/404"}
+	d404 := mockDownloader{0, svr.URL + "/status/404"}
 	msiDownloader404 := download.NewBlobWithMsiDownload(svr.URL+"/status/404", mockMsiProvider)
 	resp, err = download.WithRetries(nopLog(), []download.Downloader{&d404, msiDownloader404}, func(d time.Duration) { return })
 	require.NotNil(t, err, "download with retries should fail")

pkg/download/url.go

@@ -3,6 +3,13 @@ package download
 import (
 	"net/http"
 	"net/url"
+
+	"github.com/google/uuid"
+)
+
+const (
+	xMsClientRequestIdHeaderName  = "x-ms-client-request-id"
+	xMsServiceRequestIdHeaderName = "x-ms-request-id"
 )
 
 // urlDownload describes a URL to download.
@@ -17,7 +24,11 @@ func NewURLDownload(url string) Downloader {
 
 // GetRequest returns a new request to download the URL
 func (u urlDownload) GetRequest() (*http.Request, error) {
-	return http.NewRequest("GET", u.url, nil)
+	req, err := http.NewRequest("GET", u.url, nil)
+	if req != nil {
+		req.Header.Add(xMsClientRequestIdHeaderName, uuid.New().String())
+	}
+	return req, err
 }
 
 // Scrub query. Used to remove the query parts like SAS token.

pkg/download/url_test.go

@@ -25,6 +25,7 @@ func Test_urlDownload_GetRequest_goodURL(t *testing.T) {
 	r, err := d.GetRequest()
 	require.Nil(t, err, u)
 	require.NotNil(t, r, u)
+	require.NotNil(t, r.Header.Get(xMsClientRequestIdHeaderName))
 }
 
 func Test_GetUriForLogging_ScrubsQuery(t *testing.T) {