Add logging event EventResponseError (#22411)

* Add logging event EventResponseError

This event is logged whenever an azcore.ResponseError is created. The
contents are from ResponseError.Error().
Add NewResponseErrorWithErrorCode to support creating ResponseErrors
when the error code is in a non-standard location.

* cleanup

* verify no extra logs

sdk/azcore/CHANGELOG.md

@@ -1,9 +1,12 @@
 # Release History
 
-## 1.9.3 (Unreleased)
+## 1.10.0 (Unreleased)
 
 ### Features Added
 
+* Added logging event `log.EventResponseError` that will contain the contents of `ResponseError.Error()` whenever an `azcore.ResponseError` is created.
+* Added `runtime.NewResponseErrorWithErrorCode` for creating an `azcore.ResponseError` with a caller-supplied error code.
+
 ### Breaking Changes
 
 ### Bugs Fixed

sdk/azcore/internal/exported/response_error.go

@@ -13,38 +13,48 @@ import (
 	"net/http"
 	"regexp"
 
+	"github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/log"
 	"github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/shared"
 	"github.com/Azure/azure-sdk-for-go/sdk/internal/exported"
 )
 
 // NewResponseError creates a new *ResponseError from the provided HTTP response.
 // Exported as runtime.NewResponseError().
 func NewResponseError(resp *http.Response) error {
-	respErr := &ResponseError{
-		StatusCode:  resp.StatusCode,
-		RawResponse: resp,
-	}
-
 	// prefer the error code in the response header
 	if ec := resp.Header.Get(shared.HeaderXMSErrorCode); ec != "" {
-		respErr.ErrorCode = ec
-		return respErr
+		return NewResponseErrorWithErrorCode(resp, ec)
 	}
 
 	// if we didn't get x-ms-error-code, check in the response body
 	body, err := exported.Payload(resp, nil)
 	if err != nil {
+		// since we're not returning the ResponseError in this
+		// case we also don't want to write it to the log.
 		return err
 	}
 
+	var errorCode string
 	if len(body) > 0 {
-		if code := extractErrorCodeJSON(body); code != "" {
-			respErr.ErrorCode = code
-		} else if code := extractErrorCodeXML(body); code != "" {
-			respErr.ErrorCode = code
+		if fromJSON := extractErrorCodeJSON(body); fromJSON != "" {
+			errorCode = fromJSON
+		} else if fromXML := extractErrorCodeXML(body); fromXML != "" {
+			errorCode = fromXML
 		}
 	}
 
+	return NewResponseErrorWithErrorCode(resp, errorCode)
+}
+
+// NewResponseErrorWithErrorCode creates an *azcore.ResponseError from the provided HTTP response and errorCode.
+// Exported as runtime.NewResponseErrorWithErrorCode().
+func NewResponseErrorWithErrorCode(resp *http.Response, errorCode string) error {
+	respErr := &ResponseError{
+		ErrorCode:   errorCode,
+		StatusCode:  resp.StatusCode,
+		RawResponse: resp,
+	}
+	log.Write(log.EventResponseError, respErr.Error())
 	return respErr
 }
 

sdk/azcore/internal/exported/response_error_test.go

@@ -14,7 +14,9 @@ import (
 	"strings"
 	"testing"
 
+	azlog "github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/log"
 	"github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/shared"
+	"github.com/Azure/azure-sdk-for-go/sdk/internal/log"
 	"github.com/stretchr/testify/require"
 )
 
@@ -473,3 +475,76 @@ func TestNilResponseBody(t *testing.T) {
 	const expected = "Request information not available\n--------------------------------------------------------------------------------\nRESPONSE 0: \nERROR CODE UNAVAILABLE\n--------------------------------------------------------------------------------\nResponse contained no body\n--------------------------------------------------------------------------------\n"
 	require.EqualValues(t, expected, (&ResponseError{RawResponse: &http.Response{}}).Error())
 }
+
+func TestLogResponseErrorCodeInBody(t *testing.T) {
+	fakeURL, err := url.Parse("https://fakeurl.com/the/path?qp=removed")
+	require.NoError(t, err)
+	rawlog := map[log.Event][]string{}
+	log.SetListener(func(cls log.Event, s string) {
+		rawlog[cls] = append(rawlog[cls], s)
+	})
+	defer log.SetListener(nil)
+	_ = NewResponseError(&http.Response{
+		Status:     "the system is down",
+		StatusCode: http.StatusInternalServerError,
+		Body:       io.NopCloser(strings.NewReader(`{ "error": { "code": "ErrorItsBroken", "message": "it's not working" } }`)),
+		Request: &http.Request{
+			Method: http.MethodGet,
+			URL:    fakeURL,
+		},
+	})
+	const want = `GET https://fakeurl.com/the/path
+--------------------------------------------------------------------------------
+RESPONSE 500: the system is down
+ERROR CODE: ErrorItsBroken
+--------------------------------------------------------------------------------
+{
+  "error": {
+    "code": "ErrorItsBroken",
+    "message": "it's not working"
+  }
+}
+--------------------------------------------------------------------------------
+`
+	msg, ok := rawlog[azlog.EventResponseError]
+	require.True(t, ok)
+	require.Len(t, msg, 1)
+	require.EqualValues(t, want, msg[0])
+}
+
+func TestLogResponseErrorCodeInHeader(t *testing.T) {
+	fakeURL, err := url.Parse("https://fakeurl.com/the/path?qp=removed")
+	require.NoError(t, err)
+	rawlog := map[log.Event][]string{}
+	log.SetListener(func(cls log.Event, s string) {
+		rawlog[cls] = append(rawlog[cls], s)
+	})
+	defer log.SetListener(nil)
+	respHeader := http.Header{}
+	respHeader.Set(shared.HeaderXMSErrorCode, "ErrorTooManyCheats")
+	_ = NewResponseError(&http.Response{
+		Status:     "the system is down",
+		StatusCode: http.StatusInternalServerError,
+		Body:       io.NopCloser(strings.NewReader(`{ "code": "ErrorItsBroken", "message": "it's not working" }`)),
+		Header:     respHeader,
+		Request: &http.Request{
+			Method: http.MethodGet,
+			URL:    fakeURL,
+		},
+	})
+	const want = `GET https://fakeurl.com/the/path
+--------------------------------------------------------------------------------
+RESPONSE 500: the system is down
+ERROR CODE: ErrorTooManyCheats
+--------------------------------------------------------------------------------
+{
+  "code": "ErrorItsBroken",
+  "message": "it's not working"
+}
+--------------------------------------------------------------------------------
+`
+	msg, ok := rawlog[azlog.EventResponseError]
+	require.True(t, ok)
+	require.Len(t, msg, 1)
+	require.EqualValues(t, want, msg[0])
+}

sdk/azcore/internal/log/log.go

@@ -15,24 +15,36 @@ import (
 type Event = log.Event
 
 const (
-	EventRequest     = azlog.EventRequest
-	EventResponse    = azlog.EventResponse
-	EventRetryPolicy = azlog.EventRetryPolicy
-	EventLRO         = azlog.EventLRO
+	EventRequest       = azlog.EventRequest
+	EventResponse      = azlog.EventResponse
+	EventResponseError = azlog.EventResponseError
+	EventRetryPolicy   = azlog.EventRetryPolicy
+	EventLRO           = azlog.EventLRO
 )
 
+// Write invokes the underlying listener with the specified event and message.
+// If the event shouldn't be logged or there is no listener then Write does nothing.
 func Write(cls log.Event, msg string) {
 	log.Write(cls, msg)
 }
 
+// Writef invokes the underlying listener with the specified event and formatted message.
+// If the event shouldn't be logged or there is no listener then Writef does nothing.
 func Writef(cls log.Event, format string, a ...interface{}) {
 	log.Writef(cls, format, a...)
 }
 
+// SetListener will set the Logger to write to the specified listener.
 func SetListener(lst func(Event, string)) {
 	log.SetListener(lst)
 }
 
+// Should returns true if the specified log event should be written to the log.
+// By default all log events will be logged.  Call SetEvents() to limit
+// the log events for logging.
+// If no listener has been set this will return false.
+// Calling this method is useful when the message to log is computationally expensive
+// and you want to avoid the overhead if its log event is not enabled.
 func Should(cls log.Event) bool {
 	return log.Should(cls)
 }

sdk/azcore/internal/shared/constants.go

@@ -40,5 +40,5 @@ const (
 	Module = "azcore"
 
 	// Version is the semantic version (see http://semver.org) of this module.
-	Version = "v1.9.3"
+	Version = "v1.10.0"
 )

sdk/azcore/log/log.go

@@ -23,6 +23,11 @@ const (
 	// This includes information like the HTTP status code, headers, and request URL.
 	EventResponse Event = "Response"
 
+	// EventResponseError entries contain information about HTTP responses that returned
+	// an *azcore.ResponseError (i.e. responses with a non 2xx HTTP status code).
+	// This includes the contents of ResponseError.Error().
+	EventResponseError Event = "ResponseError"
+
 	// EventRetryPolicy entries contain information specific to the retry policy in use.
 	EventRetryPolicy Event = "Retry"
 

sdk/azcore/runtime/errors.go

@@ -14,6 +14,14 @@ import (
 
 // NewResponseError creates an *azcore.ResponseError from the provided HTTP response.
 // Call this when a service request returns a non-successful status code.
+// The error code will be extracted from the *http.Response, either from the x-ms-error-code
+// header (preferred) or attempted to be parsed from the response body.
 func NewResponseError(resp *http.Response) error {
 	return exported.NewResponseError(resp)
 }
+
+// NewResponseErrorWithErrorCode creates an *azcore.ResponseError from the provided HTTP response and errorCode.
+// Use this variant when the error code is in a non-standard location.
+func NewResponseErrorWithErrorCode(resp *http.Response, errorCode string) error {
+	return exported.NewResponseErrorWithErrorCode(resp, errorCode)
+}

sdk/azcore/runtime/errors_test.go

@@ -0,0 +1,52 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.
+
+package runtime
+
+import (
+	"io"
+	"net/http"
+	"net/url"
+	"strings"
+	"testing"
+
+	"github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/exported"
+	"github.com/stretchr/testify/require"
+)
+
+func TestNewResponseError(t *testing.T) {
+	fakeURL, err := url.Parse("https://contoso.com")
+	require.NoError(t, err)
+	err = NewResponseError(&http.Response{
+		Status:     "the system is down",
+		StatusCode: http.StatusInternalServerError,
+		Body:       io.NopCloser(strings.NewReader(`{ "code": "ErrorItsBroken", "message": "it's not working" }`)),
+		Request: &http.Request{
+			Method: http.MethodGet,
+			URL:    fakeURL,
+		},
+	})
+	var respErr *exported.ResponseError
+	require.ErrorAs(t, err, &respErr)
+	require.EqualValues(t, http.StatusInternalServerError, respErr.StatusCode)
+	require.EqualValues(t, "ErrorItsBroken", respErr.ErrorCode)
+	require.NotNil(t, respErr.RawResponse)
+}
+
+func TestNewResponseErrorWithErrorCode(t *testing.T) {
+	fakeURL, err := url.Parse("https://contoso.com")
+	require.NoError(t, err)
+	err = NewResponseErrorWithErrorCode(&http.Response{
+		Status:     "the system is down",
+		StatusCode: http.StatusInternalServerError,
+		Request: &http.Request{
+			Method: http.MethodGet,
+			URL:    fakeURL,
+		},
+	}, "ErrorItsBroken")
+	var respErr *exported.ResponseError
+	require.ErrorAs(t, err, &respErr)
+	require.EqualValues(t, http.StatusInternalServerError, respErr.StatusCode)
+	require.EqualValues(t, "ErrorItsBroken", respErr.ErrorCode)
+	require.NotNil(t, respErr.RawResponse)
+}