diff --git a/src/internal/m365/graph/http_wrapper.go b/src/internal/m365/graph/http_wrapper.go index fdffb583f..0948b9b9e 100644 --- a/src/internal/m365/graph/http_wrapper.go +++ b/src/internal/m365/graph/http_wrapper.go @@ -105,7 +105,7 @@ func (hw httpWrapper) Request( // retry in the event of a `stream error`, which is not // a common expectation. for i := 0; i < hw.config.maxConnectionRetries+1; i++ { - ictx := clues.Add(ctx, "request_retry_iter", i) + ctx = clues.Add(ctx, "request_retry_iter", i) resp, err = hw.client.Do(req) @@ -114,15 +114,15 @@ func (hw httpWrapper) Request( } if IsErrApplicationThrottled(err) { - return nil, Stack(ictx, clues.Stack(ErrApplicationThrottled, err)) + return nil, Stack(ctx, clues.Stack(ErrApplicationThrottled, err)) } var http2StreamErr http2.StreamError if !errors.As(err, &http2StreamErr) { - return nil, Stack(ictx, err) + return nil, Stack(ctx, err) } - logger.Ctx(ictx).Debug("http2 stream error") + logger.Ctx(ctx).Debug("http2 stream error") events.Inc(events.APICall, "streamerror") time.Sleep(3 * time.Second) @@ -132,6 +132,8 @@ func (hw httpWrapper) Request( return nil, Stack(ctx, err) } + logResp(ctx, resp) + return resp, nil } diff --git a/src/internal/m365/graph/logging.go b/src/internal/m365/graph/logging.go new file mode 100644 index 000000000..4f96ae926 --- /dev/null +++ b/src/internal/m365/graph/logging.go @@ -0,0 +1,72 @@ +package graph + +import ( + "context" + "net/http" + "net/http/httputil" + "os" + + "github.com/alcionai/corso/src/pkg/logger" +) + +const ( + // 1 MB + logMBLimit = 1 * 1024 * 1024 + logGraphRequestsEnvKey = "LOG_GRAPH_REQUESTS" + log2xxGraphRequestsEnvKey = "LOG_2XX_GRAPH_REQUESTS" + log2xxGraphResponseEnvKey = "LOG_2XX_GRAPH_RESPONSES" +) + +// special cases where we always dump the response body, since the response +// details might be critical to understanding the response when debugging. +func shouldLogRespBody(resp *http.Response) bool { + return logger.DebugAPIFV || + os.Getenv(logGraphRequestsEnvKey) != "" || + resp.StatusCode == http.StatusBadRequest || + resp.StatusCode == http.StatusForbidden || + resp.StatusCode == http.StatusConflict +} + +func logResp(ctx context.Context, resp *http.Response) { + var ( + log = logger.Ctx(ctx) + respClass = resp.StatusCode / 100 + + // special cases where we always dump the response body, since the response + // details might be critical to understanding the response when debugging. + logBody = shouldLogRespBody(resp) + ) + + // special case: always info-level status 429 logs + if resp.StatusCode == http.StatusTooManyRequests { + log.With("response", getRespDump(ctx, resp, logBody)). + Info("graph api throttling") + return + } + + // Log api calls according to api debugging configurations. + switch respClass { + case 2: + if logBody { + // only dump the body if it's under a size limit. We don't want to copy gigs into memory for a log. + dump := getRespDump(ctx, resp, os.Getenv(log2xxGraphResponseEnvKey) != "" && resp.ContentLength < logMBLimit) + log.Infow("2xx graph api resp", "response", dump) + } + case 3: + log.With("redirect_location", LoggableURL(resp.Header.Get(locationHeader))). + With("response", getRespDump(ctx, resp, false)). + Info("graph api redirect: " + resp.Status) + default: + log.With("response", getRespDump(ctx, resp, logBody)). + Error("graph api error: " + resp.Status) + } +} + +func getRespDump(ctx context.Context, resp *http.Response, getBody bool) string { + respDump, err := httputil.DumpResponse(resp, getBody) + if err != nil { + logger.CtxErr(ctx, err).Error("dumping http response") + } + + return string(respDump) +} diff --git a/src/internal/m365/graph/middleware.go b/src/internal/m365/graph/middleware.go index 63789ab23..d5935a5b0 100644 --- a/src/internal/m365/graph/middleware.go +++ b/src/internal/m365/graph/middleware.go @@ -4,8 +4,6 @@ import ( "context" "io" "net/http" - "net/http/httputil" - "os" "strconv" "strings" "time" @@ -115,9 +113,6 @@ func LoggableURL(url string) pii.SafeURL { } } -// 1 MB -const logMBLimit = 1 * 1048576 - func (mw *LoggingMiddleware) Intercept( pipeline khttp.Pipeline, middlewareIndex int, @@ -138,56 +133,11 @@ func (mw *LoggingMiddleware) Intercept( "resp_status_code", resp.StatusCode, "resp_content_len", resp.ContentLength) - var ( - log = logger.Ctx(ctx) - respClass = resp.StatusCode / 100 - - // special cases where we always dump the response body, since the response - // details might be critical to understanding the response when debugging. - logBody = logger.DebugAPIFV || - os.Getenv(logGraphRequestsEnvKey) != "" || - resp.StatusCode == http.StatusBadRequest || - resp.StatusCode == http.StatusForbidden || - resp.StatusCode == http.StatusConflict - ) - - // special case: always info-level status 429 logs - if resp.StatusCode == http.StatusTooManyRequests { - log.With("response", getRespDump(ctx, resp, logBody)). - Info("graph api throttling") - - return resp, err - } - - // Log api calls according to api debugging configurations. - switch respClass { - case 2: - if logBody { - // only dump the body if it's under a size limit. We don't want to copy gigs into memory for a log. - dump := getRespDump(ctx, resp, os.Getenv(log2xxGraphResponseEnvKey) != "" && resp.ContentLength < logMBLimit) - log.Infow("2xx graph api resp", "response", dump) - } - case 3: - log.With("redirect_location", LoggableURL(resp.Header.Get(locationHeader))). - With("response", getRespDump(ctx, resp, false)). - Info("graph api redirect: " + resp.Status) - default: - log.With("response", getRespDump(ctx, resp, logBody)). - Error("graph api error: " + resp.Status) - } + logResp(ctx, resp) return resp, err } -func getRespDump(ctx context.Context, resp *http.Response, getBody bool) string { - respDump, err := httputil.DumpResponse(resp, getBody) - if err != nil { - logger.CtxErr(ctx, err).Error("dumping http response") - } - - return string(respDump) -} - // --------------------------------------------------------------------------- // Retry & Backoff // --------------------------------------------------------------------------- diff --git a/src/internal/m365/graph/service.go b/src/internal/m365/graph/service.go index eedda99df..0b54b5589 100644 --- a/src/internal/m365/graph/service.go +++ b/src/internal/m365/graph/service.go @@ -23,18 +23,15 @@ import ( ) const ( - logGraphRequestsEnvKey = "LOG_GRAPH_REQUESTS" - log2xxGraphRequestsEnvKey = "LOG_2XX_GRAPH_REQUESTS" - log2xxGraphResponseEnvKey = "LOG_2XX_GRAPH_RESPONSES" - defaultMaxRetries = 3 - defaultDelay = 3 * time.Second - locationHeader = "Location" - rateLimitHeader = "RateLimit-Limit" - rateRemainingHeader = "RateLimit-Remaining" - rateResetHeader = "RateLimit-Reset" - retryAfterHeader = "Retry-After" - retryAttemptHeader = "Retry-Attempt" - defaultHTTPClientTimeout = 1 * time.Hour + defaultMaxRetries = 3 + defaultDelay = 3 * time.Second + locationHeader = "Location" + rateLimitHeader = "RateLimit-Limit" + rateRemainingHeader = "RateLimit-Remaining" + rateResetHeader = "RateLimit-Reset" + retryAfterHeader = "Retry-After" + retryAttemptHeader = "Retry-Attempt" + defaultHTTPClientTimeout = 1 * time.Hour ) type QueryParams struct {