Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log cancelled and failed requests #919

Merged
merged 2 commits into from
May 14, 2024
Merged

Log cancelled and failed requests #919

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
84dfe03
log on context timeout
mgyucht May 8, 2024
4deafb4
address comments
mgyucht May 14, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions apierr/errors.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -224,6 +224,7 @@ func parseUnknownError(resp *http.Response, requestBody, responseBody []byte, er

func MakeUnexpectedError(resp *http.Response, err error, requestBody, responseBody []byte) error {
rts := httplog.RoundTripStringer{
Request: resp.Request,
mgyucht marked this conversation as resolved.
Show resolved Hide resolved
Response: resp,
Err: err,
RequestBody: requestBody,
Expand Down
18 changes: 10 additions & 8 deletions httpclient/api_client.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -263,26 +263,27 @@ func (c *ApiClient) attempt(
if pctx.Err() == nil && uerr.Err == context.Canceled {
uerr.Err = fmt.Errorf("request timed out after %s of inactivity", c.config.HTTPTimeout)
}
return c.handleError(ctx, err, requestBody)
}

// If there is a response body, wrap it to extend the request timeout while it is being read.
if response != nil && response.Body != nil {
response.Body = newResponseBodyTicker(ticker, response.Body)
} else {
// If there is no response body, the request has completed and there
// is no need to extend the timeout. Cancel the context to clean up
// the underlying goroutine.
// If there is no response body or an error is returned, the request
// has completed and there is no need to extend the timeout. Cancel
// the context to clean up the underlying goroutine.
ticker.Cancel()
}

// By this point, the request body has certainly been consumed.
responseWrapper, err := common.NewResponseWrapper(response, requestBody)
if err != nil {
return c.failRequest(ctx, "failed while reading response", err)
var responseWrapper common.ResponseWrapper
if err == nil {
responseWrapper, err = common.NewResponseWrapper(response, requestBody)
}
if err == nil {
err = c.config.ErrorMapper(ctx, responseWrapper)
}

err = c.config.ErrorMapper(ctx, responseWrapper)
defer c.recordRequestLog(ctx, request, response, err, requestBody.DebugBytes, responseWrapper.DebugBytes)

if err == nil {
Expand All @@ -307,6 +308,7 @@ func (c *ApiClient) recordRequestLog(
return
}
message := httplog.RoundTripStringer{
Request: request,
Response: response,
Err: err,
RequestBody: requestBody,
Expand Down
74 changes: 45 additions & 29 deletions httpclient/api_client_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -334,32 +334,37 @@ func (l *BufferLogger) Enabled(_ context.Context, level logger.Level) bool {
}

func (l *BufferLogger) Tracef(_ context.Context, format string, v ...interface{}) {
l.WriteString(fmt.Sprintf("[TRACE] "+format, v...))
l.WriteString(fmt.Sprintf("[TRACE] "+format+"\n", v...))
}

func (l *BufferLogger) Debugf(_ context.Context, format string, v ...interface{}) {
l.WriteString(fmt.Sprintf("[DEBUG] "+format, v...))
l.WriteString(fmt.Sprintf("[DEBUG] "+format+"\n", v...))
}

func (l *BufferLogger) Infof(_ context.Context, format string, v ...interface{}) {
l.WriteString(fmt.Sprintf("[INFO] "+format, v...))
l.WriteString(fmt.Sprintf("[INFO] "+format+"\n", v...))
}

func (l *BufferLogger) Warnf(_ context.Context, format string, v ...interface{}) {
l.WriteString(fmt.Sprintf("[WARN] "+format, v...))
l.WriteString(fmt.Sprintf("[WARN] "+format+"\n", v...))
}

func (l *BufferLogger) Errorf(_ context.Context, format string, v ...interface{}) {
l.WriteString(fmt.Sprintf("[ERROR] "+format, v...))
l.WriteString(fmt.Sprintf("[ERROR] "+format+"\n", v...))
}

func TestSimpleResponseRedaction(t *testing.T) {
func configureBufferedLogger() (*BufferLogger, func()) {
mgyucht marked this conversation as resolved.
Show resolved Hide resolved
prevLogger := logger.DefaultLogger
bufLogger := &BufferLogger{}
logger.DefaultLogger = bufLogger
defer func() {
return bufLogger, func() {
logger.DefaultLogger = prevLogger
}()
}
}

func TestSimpleResponseRedaction(t *testing.T) {
bufLogger, resetLogger := configureBufferedLogger()
defer resetLogger()

c := NewApiClient(ClientConfig{
DebugTruncateBytes: 16,
Expand Down Expand Up @@ -402,12 +407,8 @@ func TestSimpleResponseRedaction(t *testing.T) {
}

func TestInlineArrayDebugging(t *testing.T) {
prevLogger := logger.DefaultLogger
bufLogger := &BufferLogger{}
logger.DefaultLogger = bufLogger
defer func() {
logger.DefaultLogger = prevLogger
}()
bufLogger, resetLogger := configureBufferedLogger()
defer resetLogger()

c := NewApiClient(ClientConfig{
DebugTruncateBytes: 2048,
Expand Down Expand Up @@ -437,16 +438,13 @@ func TestInlineArrayDebugging(t *testing.T) {
< {
< "foo": "bar"
< }
< ]`, bufLogger.String())
< ]
`, bufLogger.String())
}

func TestInlineArrayDebugging_StreamResponse(t *testing.T) {
prevLogger := logger.DefaultLogger
bufLogger := &BufferLogger{}
logger.DefaultLogger = bufLogger
defer func() {
logger.DefaultLogger = prevLogger
}()
bufLogger, resetLogger := configureBufferedLogger()
defer resetLogger()

c := NewApiClient(ClientConfig{
DebugTruncateBytes: 2048,
Expand All @@ -470,16 +468,13 @@ func TestInlineArrayDebugging_StreamResponse(t *testing.T) {

require.Equal(t, `[DEBUG] GET /a?a=3&b=0&c=23
<
< <Streaming response>`, bufLogger.String())
< <Streaming response>
`, bufLogger.String())
}

func TestLogQueryParametersWithPercent(t *testing.T) {
prevLogger := logger.DefaultLogger
bufLogger := &BufferLogger{}
logger.DefaultLogger = bufLogger
defer func() {
logger.DefaultLogger = prevLogger
}()
bufLogger, resetLogger := configureBufferedLogger()
defer resetLogger()

c := NewApiClient(ClientConfig{
DebugTruncateBytes: 2048,
Expand All @@ -502,7 +497,28 @@ func TestLogQueryParametersWithPercent(t *testing.T) {
<
< {
< "foo": "bar"
< }`, bufLogger.String())
< }
`, bufLogger.String())
}

func TestLogCancelledRequest(t *testing.T) {
bufLogger, resetLogger := configureBufferedLogger()
defer resetLogger()

ctx, cancel := context.WithCancel(context.Background())
c := NewApiClient(ClientConfig{
DebugTruncateBytes: 2048,
Transport: hc(func(r *http.Request) (*http.Response, error) {
cancel()
return nil, ctx.Err()
}),
})
err := c.Do(context.Background(), "GET", "/a")
assert.Error(t, err)
assert.Equal(t, `[DEBUG] non-retriable error: Get "/a": request timed out after 30s of inactivity
[DEBUG] GET /a
< Error: Get "/a": request timed out after 30s of inactivity
`, bufLogger.String())
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We could eliminate the first line to avoid duplication, perhaps?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we should keep it since there are two distinct things being logged: the raw request/response pair, and then the decision to not retry the error. I've reordered them so that there is a logical flow in the log output.

}

func TestStreamRequestFromFileWithReset(t *testing.T) {
Expand Down
34 changes: 18 additions & 16 deletions logger/httplog/round_trip_stringer.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@ import (
)

type RoundTripStringer struct {
Request *http.Request
Response *http.Response
Err error
RequestBody []byte
Expand Down Expand Up @@ -45,22 +46,21 @@ func (r RoundTripStringer) writeHeaders(sb *strings.Builder, prefix string, head
}

func (r RoundTripStringer) String() string {
request := r.Response.Request
sb := strings.Builder{}
sb.WriteString(fmt.Sprintf("%s %s", request.Method,
escapeNewLines(request.URL.Path)))
if request.URL.RawQuery != "" {
sb.WriteString(fmt.Sprintf("%s %s", r.Request.Method,
escapeNewLines(r.Request.URL.Path)))
if r.Request.URL.RawQuery != "" {
sb.WriteString("?")
q, _ := url.QueryUnescape(request.URL.RawQuery)
q, _ := url.QueryUnescape(r.Request.URL.RawQuery)
sb.WriteString(q)
}
sb.WriteString("\n")
if r.DebugHeaders {
sb.WriteString("> * Host: ")
sb.WriteString(escapeNewLines(request.Host))
sb.WriteString(escapeNewLines(r.Request.Host))
sb.WriteString("\n")
if len(request.Header) > 0 {
r.writeHeaders(&sb, "> ", request.Header)
if len(r.Request.Header) > 0 {
r.writeHeaders(&sb, "> ", r.Request.Header)
sb.WriteString("\n")
}
}
Expand All @@ -69,15 +69,17 @@ func (r RoundTripStringer) String() string {
sb.WriteString("\n")
}
sb.WriteString("< ")
if r.Response != nil {
sb.WriteString(fmt.Sprintf("%s %s", r.Response.Proto, r.Response.Status))
// Only display error on this line if the response body is empty.
// Otherwise the response body will include details about the error.
if len(r.ResponseBody) == 0 && r.Err != nil {
sb.WriteString(fmt.Sprintf(" (Error: %s)", r.Err))
}
} else {
if r.Response == nil {
sb.WriteString(fmt.Sprintf("Error: %s", r.Err))
return sb.String()
}

sb.WriteString(fmt.Sprintf("%s %s", r.Response.Proto, r.Response.Status))
// Only display error on this line if the response body is empty or the
// client failed to read the response body.
// Otherwise the response body will include details about the error.
if len(r.ResponseBody) == 0 && r.Err != nil {
sb.WriteString(fmt.Sprintf(" (Error: %s)", r.Err))
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

a question, when length of response body is > 0 (line 86), is it always true that the Err would be nil?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not necessarily. We call the ErrorMapper function that parses the response into one of the SDK errors depending on the result. If the API responds with any of our standard error codes, r.Err will be set to that.

This is just refactored from above, so there is no behavior change here.

}
if r.DebugHeaders && len(r.Response.Header) > 0 {
sb.WriteString("\n")
Expand Down
105 changes: 72 additions & 33 deletions logger/httplog/round_trip_stringer_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
package httplog

import (
"errors"
"net/http"
"net/url"
"testing"
Expand All @@ -10,14 +11,14 @@ import (

func TestNoHeadersNoBody(t *testing.T) {
res := RoundTripStringer{
Response: &http.Response{
Request: &http.Request{
Method: "GET",
URL: &url.URL{
Path: "/",
RawQuery: "foo=bar&baz=qux",
},
Request: &http.Request{
Method: "GET",
URL: &url.URL{
Path: "/",
RawQuery: "foo=bar&baz=qux",
},
},
Response: &http.Response{
Status: "200 OK",
Proto: "HTTP/1.1",
},
Expand All @@ -28,15 +29,15 @@ func TestNoHeadersNoBody(t *testing.T) {

func TestRequestAndResponseHaveHeadersAndBody(t *testing.T) {
res := RoundTripStringer{
Response: &http.Response{
Request: &http.Request{
Method: "GET",
URL: &url.URL{Path: "/"},
Header: http.Header{
"Foo": []string{"bar"},
"Bar": []string{"baz"},
},
Request: &http.Request{
Method: "GET",
URL: &url.URL{Path: "/"},
Header: http.Header{
"Foo": []string{"bar"},
"Bar": []string{"baz"},
},
},
Response: &http.Response{
Status: "200 OK",
Proto: "HTTP/1.1",
Header: http.Header{
Expand All @@ -62,15 +63,15 @@ func TestRequestAndResponseHaveHeadersAndBody(t *testing.T) {

func TestDoNotPrintHeadersWhenNotConfigured(t *testing.T) {
res := RoundTripStringer{
Response: &http.Response{
Request: &http.Request{
Method: "GET",
URL: &url.URL{Path: "/"},
Header: http.Header{
"Foo": []string{"bar"},
"Bar": []string{"baz"},
},
Request: &http.Request{
Method: "GET",
URL: &url.URL{Path: "/"},
Header: http.Header{
"Foo": []string{"bar"},
"Bar": []string{"baz"},
},
},
Response: &http.Response{
Status: "200 OK",
Proto: "HTTP/1.1",
Header: http.Header{
Expand All @@ -91,17 +92,17 @@ func TestDoNotPrintHeadersWhenNotConfigured(t *testing.T) {

func TestHideAuthorizationHeaderWhenConfigured(t *testing.T) {
res := RoundTripStringer{
Response: &http.Response{
Request: &http.Request{
Method: "GET",
URL: &url.URL{Path: "/"},
Header: http.Header{
"Foo": []string{"bar"},
"Authorization": []string{"baz"},
"X-Databricks-Azure-SP-Management-Token": []string{"open sesame"},
"X-Databricks-GCP-SA-Access-Token": []string{"alohamora"},
},
Request: &http.Request{
Method: "GET",
URL: &url.URL{Path: "/"},
Header: http.Header{
"Foo": []string{"bar"},
"Authorization": []string{"baz"},
"X-Databricks-Azure-SP-Management-Token": []string{"open sesame"},
"X-Databricks-GCP-SA-Access-Token": []string{"alohamora"},
},
},
Response: &http.Response{
Status: "200 OK",
Proto: "HTTP/1.1",
},
Expand All @@ -121,3 +122,41 @@ func TestHideAuthorizationHeaderWhenConfigured(t *testing.T) {
< HTTP/1.1 200 OK
< response-hello`, res)
}

func TestNilResponse(t *testing.T) {
res := RoundTripStringer{
Request: &http.Request{
Method: "GET",
URL: &url.URL{Path: "/"},
},
Err: &url.Error{
Op: "Get",
URL: "http://example.com",
Err: errors.New("request timed out after 1m0s of inactivity"),
},
}.String()
assert.Equal(t, `GET /
< Error: Get "http://example.com": request timed out after 1m0s of inactivity`, res)
}

func TestFailureToConsumeResponse(t *testing.T) {
res := RoundTripStringer{
Request: &http.Request{
Method: "GET",
URL: &url.URL{Path: "/"},
},
Response: &http.Response{
Status: "200 OK",
Proto: "HTTP/1.1",
Header: http.Header{
"Foo": []string{"bar"},
},
},
Err: errors.New("failed to read response body"),
DebugHeaders: true,
}.String()
assert.Equal(t, `GET /
> * Host:
< HTTP/1.1 200 OK (Error: failed to read response body)
< * Foo: ... (3 more bytes)`, res)
}