cleanup graph logging, remove 2xx test logs (#2836)

Removes 2xx query logging from CI testing, and
slightly refactors the logging middleware to make
better use of clues and minimize boilerplate.

---

#### Does this PR need a docs update or release note?

- [x]  No

#### Type of change

- [x] 🤖 Test
- [x] 🧹 Tech Debt/Cleanup

#### Test Plan

- [x] 💚 E2E
This commit is contained in:
Keepers 2023-03-17 10:00:22 -06:00 committed by GitHub
parent 83bddf79a0
commit 91328d9898
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23

View File

@ -1,6 +1,8 @@
package graph
import (
"context"
"fmt"
"net/http"
"net/http/httputil"
"os"
@ -16,6 +18,7 @@ import (
msgraphgocore "github.com/microsoftgraph/msgraph-sdk-go-core"
"github.com/pkg/errors"
"github.com/alcionai/clues"
"github.com/alcionai/corso/src/pkg/account"
"github.com/alcionai/corso/src/pkg/logger"
"github.com/alcionai/corso/src/pkg/path"
@ -23,6 +26,7 @@ import (
const (
logGraphRequestsEnvKey = "LOG_GRAPH_REQUESTS"
log2xxGraphRequestsEnvKey = "LOG_2XX_GRAPH_REQUESTS"
numberOfRetries = 3
retryAttemptHeader = "Retry-Attempt"
retryAfterHeader = "Retry-After"
@ -262,34 +266,31 @@ func (handler *LoggingMiddleware) Intercept(
req *http.Request,
) (*http.Response, error) {
var (
ctx = req.Context()
ctx = clues.Add(
req.Context(),
"method", req.Method,
"url", req.URL, // TODO: pii
"request_len", req.ContentLength,
)
log = logger.Ctx(ctx)
resp, err = pipeline.Next(req, middlewareIndex)
)
if strings.Contains(req.URL.String(), "users//") {
logger.Ctx(ctx).Errorw("malformed request url: missing resource", "url", req.URL)
log.Error("malformed request url: missing resource")
}
if resp == nil {
return resp, err
}
ctx = clues.Add(ctx, "status", resp.Status, "statusCode", resp.StatusCode)
// Return immediately if the response is good (2xx).
// If api logging is toggled, log a body-less dump of the request/resp.
if (resp.StatusCode / 100) == 2 {
if logger.DebugAPI || os.Getenv(logGraphRequestsEnvKey) != "" {
respDump, _ := httputil.DumpResponse(resp, false)
metadata := []any{
"method", req.Method,
"status", resp.Status,
"statusCode", resp.StatusCode,
"requestLen", req.ContentLength,
"url", req.URL,
"response", respDump,
}
logger.Ctx(ctx).Debugw("2xx graph api resp", metadata...)
if logger.DebugAPI || os.Getenv(log2xxGraphRequestsEnvKey) != "" {
log.Debugw("2xx graph api resp", "response", getRespDump(ctx, resp, false))
}
return resp, err
@ -300,46 +301,37 @@ func (handler *LoggingMiddleware) Intercept(
// Otherwise, throttling cases and other non-2xx responses are logged
// with a slimmer reference for telemetry/supportability purposes.
if logger.DebugAPI || os.Getenv(logGraphRequestsEnvKey) != "" {
respDump, _ := httputil.DumpResponse(resp, true)
log.Errorw("non-2xx graph api response", "response", getRespDump(ctx, resp, true))
metadata := []any{
"method", req.Method,
"status", resp.Status,
"statusCode", resp.StatusCode,
"requestLen", req.ContentLength,
"url", req.URL,
"response", string(respDump),
return resp, err
}
logger.Ctx(ctx).Errorw("non-2xx graph api response", metadata...)
} else {
msg := fmt.Sprintf("graph api error: %s", resp.Status)
// special case for supportability: log all throttling cases.
if resp.StatusCode == http.StatusTooManyRequests {
logger.Ctx(ctx).Infow("graph api throttling",
"method", req.Method,
"url", req.URL,
log.With(
"limit", resp.Header.Get(rateLimitHeader),
"remaining", resp.Header.Get(rateRemainingHeader),
"reset", resp.Header.Get(rateResetHeader))
} else if resp.StatusCode == http.StatusBadRequest {
respDump, _ := httputil.DumpResponse(resp, true)
logger.Ctx(ctx).Infow(
"graph api error",
"status", resp.Status,
"method", req.Method,
"url", req.URL,
"response", string(respDump),
)
} else if resp.StatusCode/100 != 2 {
logger.Ctx(ctx).
With("status", resp.Status, "method", req.Method, "url", req.URL).
Infof("graph api error: %s", resp.Status)
}
} else if resp.StatusCode/100 == 4 {
log.With("response", getRespDump(ctx, resp, true))
}
log.Info(msg)
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)
}
// Intercept implements the interface and evaluates whether to retry a failed request.
func (middleware RetryHandler) Intercept(
pipeline khttp.Pipeline,