From 89ee9d0ee549b93b9611cba0cab00b1b76411972 Mon Sep 17 00:00:00 2001 From: Joel Hendrix Date: Wed, 21 Feb 2024 14:04:53 -0800 Subject: [PATCH] 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 | 5 +- .../internal/exported/response_error.go | 32 +++++--- .../internal/exported/response_error_test.go | 75 +++++++++++++++++++ sdk/azcore/internal/log/log.go | 20 ++++- sdk/azcore/internal/shared/constants.go | 2 +- sdk/azcore/log/log.go | 5 ++ sdk/azcore/runtime/errors.go | 8 ++ sdk/azcore/runtime/errors_test.go | 52 +++++++++++++ 8 files changed, 182 insertions(+), 17 deletions(-) create mode 100644 sdk/azcore/runtime/errors_test.go diff --git a/sdk/azcore/CHANGELOG.md b/sdk/azcore/CHANGELOG.md index 0fa6d67a614b..30a0d246f9b1 100644 --- a/sdk/azcore/CHANGELOG.md +++ b/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 diff --git a/sdk/azcore/internal/exported/response_error.go b/sdk/azcore/internal/exported/response_error.go index f243552885d1..bd348b868bf6 100644 --- a/sdk/azcore/internal/exported/response_error.go +++ b/sdk/azcore/internal/exported/response_error.go @@ -13,6 +13,7 @@ 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" ) @@ -20,31 +21,40 @@ import ( // 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 } diff --git a/sdk/azcore/internal/exported/response_error_test.go b/sdk/azcore/internal/exported/response_error_test.go index 49a234a93573..10e3f3997428 100644 --- a/sdk/azcore/internal/exported/response_error_test.go +++ b/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]) +} diff --git a/sdk/azcore/internal/log/log.go b/sdk/azcore/internal/log/log.go index 0684cb317390..5cb87de2cb56 100644 --- a/sdk/azcore/internal/log/log.go +++ b/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) } diff --git a/sdk/azcore/internal/shared/constants.go b/sdk/azcore/internal/shared/constants.go index d580c246c868..330bf9a60b73 100644 --- a/sdk/azcore/internal/shared/constants.go +++ b/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" ) diff --git a/sdk/azcore/log/log.go b/sdk/azcore/log/log.go index 7bde29d0a462..f260dac3637c 100644 --- a/sdk/azcore/log/log.go +++ b/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" diff --git a/sdk/azcore/runtime/errors.go b/sdk/azcore/runtime/errors.go index 6d03b291ebff..c0d56158e229 100644 --- a/sdk/azcore/runtime/errors.go +++ b/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) +} diff --git a/sdk/azcore/runtime/errors_test.go b/sdk/azcore/runtime/errors_test.go new file mode 100644 index 000000000000..135d2efa25fb --- /dev/null +++ b/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) +}