feat: always log bolt request analytics in debug mode (#68)

Co-authored-by: Kote <km@projectn.co>
project-n-oss · Aug 11, 2023 · f8d8ed0 · f8d8ed0
1 parent 5c75439
commit f8d8ed0
Show file tree

Hide file tree

Showing 2 changed files with 89 additions and 28 deletions.
diff --git a/api/api.go b/api/api.go
@@ -67,7 +67,12 @@ func (a *Api) routeBase(w http.ResponseWriter, req *http.Request) {
 		dumpRequest(sess.Logger(), boltReq)
 	}
 
-	resp, failover, err := sess.br.DoBoltRequest(sess.Logger(), boltReq)
+	resp, failover, analytics, err := sess.br.DoBoltRequest(sess.Logger(), boltReq)
+
+	if sess.Logger().Level() == zap.DebugLevel {
+		dumpAnalytics(sess.Logger(), analytics, err)
+	}
+
 	if err != nil {
 		a.InternalError(sess.Logger(), w, err)
 		return
@@ -111,3 +116,28 @@ func dumpRequest(logger *zap.Logger, boltReq *boltrouter.BoltRequest) {
 
 	logger.Debug("BoltRequest dump", zap.String("bolt", string(boltDump)), zap.String("aws", string(awsDump)))
 }
+
+func dumpAnalytics(logger *zap.Logger, analytics *boltrouter.BoltRequestAnalytics, err error) {
+	defaultValue := "N/A"
+
+	logger.Debug("BoltRequestAnalytics dump",
+		zap.Any("ObjectKey", orDefault(analytics.ObjectKey, defaultValue)),
+		zap.Any("RequestBodySize", orDefault(analytics.RequestBodySize, defaultValue)),
+		zap.Any("Method", orDefault(analytics.Method, defaultValue)),
+		zap.Any("InitialRequestTarget", orDefault(analytics.InitialRequestTarget, defaultValue)),
+		zap.Any("InitialRequestTargetReason", orDefault(analytics.InitialRequestTargetReason, defaultValue)),
+		zap.Any("BoltReplicaIp", orDefault(analytics.BoltRequestUrl, defaultValue)),
+		zap.Any("BoltRequestDuration", orDefault(analytics.BoltRequestDuration, defaultValue)),
+		zap.Any("BoltRequestResponseStatusCode", orDefault(analytics.BoltRequestResponseStatusCode, defaultValue)),
+		zap.Any("AwsRequestDuration", orDefault(analytics.AwsRequestDuration, defaultValue)),
+		zap.Any("AwsRequestResponseStatusCode", orDefault(analytics.AwsRequestResponseStatusCode, defaultValue)),
+		zap.Any("Error", orDefault(err, defaultValue)),
+	)
+}
+
+func orDefault(value interface{}, defaultValue interface{}) interface{} {
+	if value == nil || value == "" || value == 0 {
+		return defaultValue
+	}
+	return value
+}
diff --git a/boltrouter/bolt_request.go b/boltrouter/bolt_request.go
@@ -17,6 +17,19 @@ type BoltRequest struct {
 	Aws  *http.Request
 }
 
+type BoltRequestAnalytics struct {
+	ObjectKey                     string
+	RequestBodySize               int
+	Method                        string
+	InitialRequestTarget          string
+	InitialRequestTargetReason    string
+	BoltRequestUrl                string
+	BoltRequestDuration           time.Duration
+	BoltRequestResponseStatusCode int
+	AwsRequestDuration            time.Duration
+	AwsRequestResponseStatusCode  int
+}
+
 // NewBoltRequest transforms the passed in intercepted aws http.Request and returns
 // a new http.Request Ready to be sent to Bolt.
 // This new http.Request is routed to the correct Bolt endpoint and signed correctly.
@@ -158,10 +171,25 @@ func newFailoverAwsRequest(ctx context.Context, req *http.Request, awsCred aws.C
 // DoBoltRequest sends an HTTP Bolt request and returns an HTTP response, following policy (such as redirects, cookies, auth) as configured on the client.
 // DoBoltRequest will failover to AWS if the Bolt request fails and the config.Failover is set to true.
 // DoboltRequest will return a bool indicating if the request was a failover.
-func (br *BoltRouter) DoBoltRequest(logger *zap.Logger, boltReq *BoltRequest) (*http.Response, bool, error) {
+// DoBoltRequest will return a BoltRequestAnalytics struct with analytics about the request.
+func (br *BoltRouter) DoBoltRequest(logger *zap.Logger, boltReq *BoltRequest) (*http.Response, bool, *BoltRequestAnalytics, error) {
 	initialRequestTarget, reason, err := br.SelectInitialRequestTarget()
+
+	boltRequestAnalytics := &BoltRequestAnalytics{
+		ObjectKey:                     boltReq.Bolt.URL.Path,
+		RequestBodySize:               int(boltReq.Bolt.ContentLength),
+		Method:                        boltReq.Bolt.Method,
+		InitialRequestTarget:          initialRequestTarget,
+		InitialRequestTargetReason:    reason,
+		BoltRequestUrl:                boltReq.Bolt.URL.Hostname(),
+		BoltRequestDuration:           time.Duration(0),
+		BoltRequestResponseStatusCode: -1,
+		AwsRequestDuration:            -1,
+		AwsRequestResponseStatusCode:  -1,
+	}
+
 	if err != nil {
-		return nil, false, err
+		return nil, false, boltRequestAnalytics, err
 	}
 
 	logger.Debug("initial request target", zap.String("target", initialRequestTarget), zap.String("reason", reason))
@@ -170,55 +198,58 @@ func (br *BoltRouter) DoBoltRequest(logger *zap.Logger, boltReq *BoltRequest) (*
 		beginTime := time.Now()
 		resp, err := br.boltHttpClient.Do(boltReq.Bolt)
 		duration := time.Since(beginTime)
-		LogAnalytics(logger, boltReq, duration, initialRequestTarget, reason, resp, false)
+		boltRequestAnalytics.BoltRequestDuration = duration
 		if err != nil {
-			return resp, false, err
+			if resp != nil {
+				boltRequestAnalytics.BoltRequestResponseStatusCode = resp.StatusCode
+			}
+			return resp, false, boltRequestAnalytics, err
 		} else if !StatusCodeIs2xx(resp.StatusCode) && br.config.Failover {
 			b, _ := io.ReadAll(resp.Body)
 			resp.Body.Close()
 			logger.Error("bolt request failed", zap.Int("statusCode", resp.StatusCode), zap.String("body", string(b)))
 			beginTime := time.Now()
 			resp, err := http.DefaultClient.Do(boltReq.Aws)
 			duration := time.Since(beginTime)
-			LogAnalytics(logger, boltReq, duration, initialRequestTarget, reason, resp, true)
-			return resp, true, err
+			boltRequestAnalytics.AwsRequestDuration = duration
+			if err != nil {
+				if resp != nil {
+					boltRequestAnalytics.AwsRequestResponseStatusCode = resp.StatusCode
+				}
+			}
+			return resp, true, boltRequestAnalytics, err
 		}
-		return resp, false, nil
+		boltRequestAnalytics.BoltRequestResponseStatusCode = resp.StatusCode
+		return resp, false, boltRequestAnalytics, nil
 	} else {
 		beginTime := time.Now()
 		resp, err := http.DefaultClient.Do(boltReq.Aws)
 		duration := time.Since(beginTime)
-		LogAnalytics(logger, boltReq, duration, initialRequestTarget, reason, resp, false)
+		boltRequestAnalytics.AwsRequestDuration = duration
 		if err != nil {
-			return resp, false, err
+			if resp != nil {
+				boltRequestAnalytics.AwsRequestResponseStatusCode = resp.StatusCode
+			}
+			return resp, false, boltRequestAnalytics, err
 		} else if !StatusCodeIs2xx(resp.StatusCode) && resp.StatusCode == 404 {
 			// if the request to AWS failed with 404: NoSuchKey, fall back to Bolt
 			logger.Error("aws request failed, falling back to bolt", zap.Int("statusCode", resp.StatusCode))
 			beginTime := time.Now()
 			resp, err := br.boltHttpClient.Do(boltReq.Bolt)
 			duration := time.Since(beginTime)
-			LogAnalytics(logger, boltReq, duration, initialRequestTarget, reason, resp, true)
-			return resp, true, err
+			boltRequestAnalytics.BoltRequestDuration = duration
+			if err != nil {
+				if resp != nil {
+					boltRequestAnalytics.BoltRequestResponseStatusCode = resp.StatusCode
+				}
+			}
+			return resp, true, boltRequestAnalytics, err
 		}
-		return resp, false, nil
+		boltRequestAnalytics.AwsRequestResponseStatusCode = resp.StatusCode
+		return resp, false, boltRequestAnalytics, nil
 	}
 }
 
 func StatusCodeIs2xx(statusCode int) bool {
 	return statusCode >= 200 && statusCode < 300
 }
-
-// function to log analytics
-func LogAnalytics(logger *zap.Logger, boltReq *BoltRequest, duration time.Duration, initialRequestTarget string, reason string, resp *http.Response, failover bool) {
-	if logger.Level() == zap.DebugLevel {
-		logger.Debug("[ANALYTICS]",
-			zap.Int("requestBodySize", int(boltReq.Bolt.ContentLength)),
-			zap.Duration("duration", duration),
-			zap.String("method", boltReq.Bolt.Method),
-			zap.String("requestTarget", initialRequestTarget),
-			zap.String("requestTargetReason", reason),
-			zap.Int("responseCode", resp.StatusCode),
-			zap.Bool("failover", failover),
-		)
-	}
-}