From 2568bfd70db00b495e5a3c00b2741e425f1a50fa Mon Sep 17 00:00:00 2001
From: Sean Cunningham <sean.cunningham@elastic.co>
Date: Fri, 28 May 2021 14:50:11 -0400
Subject: [PATCH] Add log message to diag auth latency. Replace with metrics on
 auth round trip time in the future.

---
 cmd/fleet/auth.go | 24 ++++++++++++++++++++++++
 1 file changed, 24 insertions(+)

diff --git a/cmd/fleet/auth.go b/cmd/fleet/auth.go
index cf147fec3..b79e0cc51 100644
--- a/cmd/fleet/auth.go
+++ b/cmd/fleet/auth.go
@@ -84,17 +84,41 @@ func authApiKey(r *http.Request, client *elasticsearch.Client, c cache.Cache) (*
 }
 
 func authAgent(r *http.Request, id string, bulker bulk.Bulk, c cache.Cache) (*model.Agent, error) {
+	start := time.Now()
+
 	// authenticate
 	key, err := authApiKey(r, bulker.Client(), c)
 	if err != nil {
 		return nil, err
 	}
 
+	authTime := time.Now()
+
 	agent, err := findAgentByApiKeyId(r.Context(), bulker, key.Id)
 	if err != nil {
 		return nil, err
 	}
 
+	findTime := time.Now()
+
+	// TOOD: Remove temporary log msg to diag roundtrip speed issue on auth
+	if findTime.Sub(start) > time.Second*5 {
+		reqId := r.Header.Get(logger.HeaderRequestID)
+
+		zlog := log.With().
+			Str("agentId", id).
+			Str(EcsHttpRequestId, reqId).
+			Logger()
+
+		zlog.Debug().
+			Int64(EcsEventDuration, authTime.Sub(start).Nanoseconds()).
+			Msg("authApiKey slow")
+
+		zlog.Debug().
+			Int64(EcsEventDuration, findTime.Sub(authTime).Nanoseconds()).
+			Msg("findAgentByApiKeyId slow")
+	}
+
 	// validate key alignment
 	if agent.AccessApiKeyId != key.Id {
 		log.Info().