From 2da554f00e0a9eabf844a485c94eaa45d42feae8 Mon Sep 17 00:00:00 2001
From: Keepers <ryanfkeepers@gmail.com>
Date: Thu, 1 Jun 2023 01:01:08 -0600
Subject: [PATCH] minor logging updates (#3546)

Co-authored-by: aviator-app[bot] <48659329+aviator-app[bot]@users.noreply.github.com>
---
 src/internal/connector/graph/middleware.go | 51 ++++++++--------------
 src/internal/operations/backup.go          |  3 +-
 src/internal/operations/restore.go         |  8 +++-
 3 files changed, 26 insertions(+), 36 deletions(-)

diff --git a/src/internal/connector/graph/middleware.go b/src/internal/connector/graph/middleware.go
index 03d3a109f..bc9aabe2d 100644
--- a/src/internal/connector/graph/middleware.go
+++ b/src/internal/connector/graph/middleware.go
@@ -140,29 +140,21 @@ func (mw *LoggingMiddleware) Intercept(
 	var (
 		log       = logger.Ctx(ctx)
 		respClass = resp.StatusCode / 100
-		logExtra  = logger.DebugAPIFV || os.Getenv(logGraphRequestsEnvKey) != ""
+
+		// special cases where we always dump the response body, since the response
+		// details might be critical to understanding the response when debugging.
+		// * 400-bad-request
+		// * 403-forbidden
+		logBody = logger.DebugAPIFV ||
+			os.Getenv(logGraphRequestsEnvKey) != "" ||
+			resp.StatusCode == http.StatusBadRequest ||
+			resp.StatusCode == http.StatusForbidden
 	)
 
-	// special case: always info log 429 responses
+	// special case: always info-level status 429 logs
 	if resp.StatusCode == http.StatusTooManyRequests {
-		if logExtra {
-			log = log.With("response", getRespDump(ctx, resp, true))
-		}
-
-		log.Infow(
-			"graph api throttling",
-			"limit", resp.Header.Get(rateLimitHeader),
-			"remaining", resp.Header.Get(rateRemainingHeader),
-			"reset", resp.Header.Get(rateResetHeader),
-			"retry-after", resp.Header.Get(retryAfterHeader))
-
-		return resp, err
-	}
-
-	// special case: always dump status-400-bad-request
-	if resp.StatusCode == http.StatusBadRequest {
-		log.With("response", getRespDump(ctx, resp, true)).
-			Error("graph api error: " + resp.Status)
+		log.With("response", getRespDump(ctx, resp, logBody)).
+			Info("graph api throttling")
 
 		return resp, err
 	}
@@ -170,25 +162,18 @@ func (mw *LoggingMiddleware) Intercept(
 	// Log api calls according to api debugging configurations.
 	switch respClass {
 	case 2:
-		if logExtra {
+		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 = log.With("redirect_location", LoggableURL(resp.Header.Get(locationHeader)))
-
-		if logExtra {
-			log = log.With("response", getRespDump(ctx, resp, false))
-		}
-
-		log.Info("graph api redirect: " + resp.Status)
+		log.With("redirect_location", LoggableURL(resp.Header.Get(locationHeader))).
+			With("response", getRespDump(ctx, resp, false)).
+			Info("graph api redirect: " + resp.Status)
 	default:
-		if logExtra {
-			log = log.With("response", getRespDump(ctx, resp, true))
-		}
-
-		log.Error("graph api error: " + resp.Status)
+		log.With("response", getRespDump(ctx, resp, logBody)).
+			Error("graph api error: " + resp.Status)
 	}
 
 	return resp, err
diff --git a/src/internal/operations/backup.go b/src/internal/operations/backup.go
index 5240d2c88..5ad400bb3 100644
--- a/src/internal/operations/backup.go
+++ b/src/internal/operations/backup.go
@@ -177,7 +177,8 @@ func (op *BackupOperation) Run(ctx context.Context) (err error) {
 	ctx = clues.Add(
 		ctx,
 		"tenant_id", clues.Hide(op.account.ID()),
-		"resource_owner", clues.Hide(op.ResourceOwner.Name()),
+		"resource_owner_id", op.ResourceOwner.ID(),
+		"resource_owner_name", clues.Hide(op.ResourceOwner.Name()),
 		"backup_id", op.Results.BackupID,
 		"service", op.Selectors.Service,
 		"incremental", op.incremental)
diff --git a/src/internal/operations/restore.go b/src/internal/operations/restore.go
index 55103cec7..5b2c9bd71 100644
--- a/src/internal/operations/restore.go
+++ b/src/internal/operations/restore.go
@@ -194,6 +194,10 @@ func (op *RestoreOperation) do(
 	detailsStore streamstore.Reader,
 	start time.Time,
 ) (*details.Details, error) {
+	logger.Ctx(ctx).
+		With("control_options", op.Options, "selectors", op.Selectors).
+		Info("restoring selection")
+
 	bup, deets, err := getBackupAndDetailsFromID(
 		ctx,
 		op.BackupID,
@@ -213,7 +217,8 @@ func (op *RestoreOperation) do(
 
 	ctx = clues.Add(
 		ctx,
-		"resource_owner", bup.Selector.DiscreteOwner,
+		"resource_owner_id", bup.Selector.ID(),
+		"resource_owner_name", clues.Hide(bup.Selector.Name()),
 		"details_entries", len(deets.Entries),
 		"details_paths", len(paths),
 		"backup_snapshot_id", bup.SnapshotID,
@@ -230,7 +235,6 @@ func (op *RestoreOperation) do(
 		})
 
 	observe.Message(ctx, fmt.Sprintf("Discovered %d items in backup %s to restore", len(paths), op.BackupID))
-	logger.Ctx(ctx).With("control_options", op.Options, "selectors", op.Selectors).Info("restoring selection")
 
 	kopiaComplete, closer := observe.MessageWithCompletion(ctx, "Enumerating items in repository")
 	defer closer()