graph debug logging improvements (#4368)

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

- [x] ⛔ No

#### Type of change

- [x] 🤖 Supportability/Tests
- [x] 🧹 Tech Debt/Cleanup

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
 }
 

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)
+}

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,54 +133,9 @@ 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")
+	logResp(ctx, resp)
 
 	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)
-	}
-
-	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)
 }
 
 // ---------------------------------------------------------------------------

src/internal/m365/graph/service.go

@@ -23,9 +23,6 @@ import (
 )
 
 const (
-	logGraphRequestsEnvKey    = "LOG_GRAPH_REQUESTS"
-	log2xxGraphRequestsEnvKey = "LOG_2XX_GRAPH_REQUESTS"
-	log2xxGraphResponseEnvKey = "LOG_2XX_GRAPH_RESPONSES"
 	defaultMaxRetries        = 3
 	defaultDelay             = 3 * time.Second
 	locationHeader           = "Location"