From e53b0303dd9759aac8b8dfd49c1f24b00e2fcd85 Mon Sep 17 00:00:00 2001 From: Abhishek Pandey Date: Thu, 2 Nov 2023 18:48:37 -0700 Subject: [PATCH] Req logging --- src/internal/common/limiters/sliding_window.go | 9 +++++++++ src/internal/m365/graph/concurrency_middleware.go | 4 ++++ src/internal/m365/graph/logging.go | 9 +++++++++ src/internal/m365/graph/middleware.go | 6 ++++++ 4 files changed, 28 insertions(+) diff --git a/src/internal/common/limiters/sliding_window.go b/src/internal/common/limiters/sliding_window.go index 1ba829f34..18c02b6c4 100644 --- a/src/internal/common/limiters/sliding_window.go +++ b/src/internal/common/limiters/sliding_window.go @@ -2,6 +2,7 @@ package limiters import ( "context" + "fmt" "sync" "time" @@ -139,6 +140,14 @@ func (s *slidingWindow) nextInterval() { // Slide the fixed windows if windowSize time has elapsed. if s.currentInterval == 0 { + sum := int64(0) + for i := 0; i < int(s.numIntervals); i++ { + fmt.Printf("Curr Interval %d: %d\n", i, s.curr.count[i]) + sum += s.curr.count[i] + } + + fmt.Printf("Switching window: Total tokens issued: %d\n\n", sum) + s.prev = s.curr s.curr = fixedWindow{ count: make([]int, s.numIntervals), diff --git a/src/internal/m365/graph/concurrency_middleware.go b/src/internal/m365/graph/concurrency_middleware.go index 60762ca32..cde3a1b8e 100644 --- a/src/internal/m365/graph/concurrency_middleware.go +++ b/src/internal/m365/graph/concurrency_middleware.go @@ -102,6 +102,10 @@ var ( driveLimiter = rate.NewLimiter(drivePerSecond, driveMaxCap) // also used as the exchange service limiter defaultLimiter = rate.NewLimiter(defaultPerSecond, defaultMaxCap) + + // 10 min window, 1 second sliding interval, 10k capacity + //exchangeLimiter = limiters.NewLimiter(10*time.Minute, 100*time.Millisecond, 10000) + exchangeLimiter = limiters.NewLimiter(10*time.Minute, 1*time.Second, 10000) ) type LimiterCfg struct { diff --git a/src/internal/m365/graph/logging.go b/src/internal/m365/graph/logging.go index 4f96ae926..1d117420c 100644 --- a/src/internal/m365/graph/logging.go +++ b/src/internal/m365/graph/logging.go @@ -70,3 +70,12 @@ func getRespDump(ctx context.Context, resp *http.Response, getBody bool) string return string(respDump) } + +func getReqDump(ctx context.Context, req *http.Request) string { + reqDump, err := httputil.DumpRequest(req, true) + if err != nil { + logger.CtxErr(ctx, err).Error("dumping http response") + } + + return string(reqDump) +} diff --git a/src/internal/m365/graph/middleware.go b/src/internal/m365/graph/middleware.go index 4fd28c5fd..986f830a6 100644 --- a/src/internal/m365/graph/middleware.go +++ b/src/internal/m365/graph/middleware.go @@ -334,6 +334,12 @@ func (mw *MetricsMiddleware) Intercept( middlewareIndex int, req *http.Request, ) (*http.Response, error) { + // Log request + dump := getReqDump(req.Context(), req) + logger.Ctx(req.Context()).Debugw("making graph api req: ", + "request", dump, + "requests_so_far", mw.counter.Get(count.APICallTokensConsumed)) + var ( start = time.Now() resp, err = pipeline.Next(req, middlewareIndex)