From 8c2d7c3c18bf7744c301ee384e2c733f9ac21e99 Mon Sep 17 00:00:00 2001
From: Keepers <ryanfkeepers@gmail.com>
Date: Fri, 12 Jan 2024 13:53:25 -0700
Subject: [PATCH] log api call start-end times (#5025)

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

- [x] :no_entry: No

#### Type of change

- [x] :robot: Supportability/Tests
---
 src/pkg/services/m365/api/graph/http_wrapper.go | 16 +++++++++++-----
 src/pkg/services/m365/api/graph/service.go      | 10 ++++++++--
 2 files changed, 19 insertions(+), 7 deletions(-)

diff --git a/src/pkg/services/m365/api/graph/http_wrapper.go b/src/pkg/services/m365/api/graph/http_wrapper.go
index 57464365d..17cf51d3a 100644
--- a/src/pkg/services/m365/api/graph/http_wrapper.go
+++ b/src/pkg/services/m365/api/graph/http_wrapper.go
@@ -14,6 +14,7 @@ import (
 	"github.com/alcionai/corso/src/internal/events"
 	"github.com/alcionai/corso/src/internal/version"
 	"github.com/alcionai/corso/src/pkg/count"
+	"github.com/alcionai/corso/src/pkg/dttm"
 	"github.com/alcionai/corso/src/pkg/logger"
 )
 
@@ -129,15 +130,18 @@ func (hw httpWrapper) Request(
 			time.Sleep(hw.retryDelay)
 		}
 
-		ctx = clues.Add(ctx, "request_retry_iter", i)
+		ictx := clues.Add(
+			ctx,
+			"request_retry_iter", i,
+			"request_start_time", dttm.Now())
 
 		resp, err := hw.client.Do(req)
 		if err == nil {
-			logResp(ctx, resp)
+			logResp(ictx, resp)
 			return resp, nil
 		}
 
-		err = stackWithCoreErr(ctx, err, 1)
+		err = stackWithCoreErr(ictx, err, 1)
 		e = err
 
 		var http2StreamErr http2.StreamError
@@ -146,14 +150,16 @@ func (hw httpWrapper) Request(
 			break
 		}
 
-		logger.Ctx(ctx).Debug("http2 stream error")
+		logger.Ctx(ictx).Debug("http2 stream error")
 		events.Inc(events.APICall, "streamerror")
 
 		retriedErrors = append(retriedErrors, err.Error())
 	}
 
 	e = clues.Stack(e).
-		With("retried_errors", retriedErrors).
+		With(
+			"retried_errors", retriedErrors,
+			"request_end_time", dttm.Now()).
 		WithTrace(1).
 		OrNil()
 
diff --git a/src/pkg/services/m365/api/graph/service.go b/src/pkg/services/m365/api/graph/service.go
index ed8ccff7b..90656ce8e 100644
--- a/src/pkg/services/m365/api/graph/service.go
+++ b/src/pkg/services/m365/api/graph/service.go
@@ -19,6 +19,7 @@ import (
 	"github.com/alcionai/corso/src/internal/common/idname"
 	"github.com/alcionai/corso/src/internal/events"
 	"github.com/alcionai/corso/src/pkg/count"
+	"github.com/alcionai/corso/src/pkg/dttm"
 	"github.com/alcionai/corso/src/pkg/errs/core"
 	"github.com/alcionai/corso/src/pkg/filters"
 	"github.com/alcionai/corso/src/pkg/logger"
@@ -402,7 +403,10 @@ func (aw *adapterWrap) Send(
 			time.Sleep(aw.retryDelay)
 		}
 
-		ictx := clues.Add(ctx, "request_retry_iter", i)
+		ictx := clues.Add(
+			ctx,
+			"request_retry_iter", i,
+			"request_start_time", dttm.Now())
 
 		resp, err := aw.RequestAdapter.Send(ictx, requestInfo, constructor, errorMappings)
 		if err == nil {
@@ -434,7 +438,9 @@ func (aw *adapterWrap) Send(
 	}
 
 	e = clues.Stack(e).
-		With("retried_errors", retriedErrors).
+		With(
+			"retried_errors", retriedErrors,
+			"request_end_time", dttm.Now()).
 		WithTrace(1).
 		OrNil()