Missing user in logs bug

lib/go-rfc/http.go

@@ -43,6 +43,7 @@ const (
 	Age                = "Age"                 // RFC7234§5.1
 	Location           = "Location"            // RFC7231§7.1.2
 	Authorization      = "Authorization"       // RFC7235§4.2
+	Cookie             = "Cookie"              // RFC7873
 )
 
 // These are (some) valid values for content encoding and MIME types, for

traffic_ops/traffic_ops_golang/routing/middleware/wrappers.go

@@ -39,6 +39,7 @@ import (
 	"github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/api"
 	"github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/auth"
 	"github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/tocookie"
+	"github.com/lestrrat-go/jwx/jwt"
 )
 
 // DefaultRequestTimeout is the default request timeout, if no timeout is configured.
@@ -188,19 +189,45 @@ func GetWrapAccessLog(secret string) Middleware {
 	}
 }
 
+func getCookieToken(r *http.Request) string {
+	cookie, err := r.Cookie(tocookie.Name)
+	if err == nil && cookie != nil {
+		return cookie.Value
+	} else if r.Header.Get(rfc.Cookie) != "" && strings.Contains(r.Header.Get(rfc.Cookie), tocookie.AccessToken) {
+		cookie, err := r.Cookie(tocookie.AccessToken)
+		if err == nil && cookie != nil {
+			decodedToken, err := jwt.Parse([]byte(cookie.Value))
+			if err == nil && cookie != nil {
+				return fmt.Sprintf("%s", decodedToken.PrivateClaims()[tocookie.MojoCookie])
+			}
+		}
+	} else if r.Header.Get(rfc.Authorization) != "" && strings.Contains(r.Header.Get(rfc.Authorization), tocookie.BearerToken) {
+		givenTokenSplit := strings.Split(r.Header.Get(rfc.Authorization), " ")
+		if len(givenTokenSplit) < 2 {
+			return ""
+		}
+		decodedToken, err := jwt.Parse([]byte(givenTokenSplit[1]))
+		if err == nil && decodedToken != nil {
+			return fmt.Sprintf("%s", decodedToken.PrivateClaims()[tocookie.MojoCookie])
+		}
+		return givenTokenSplit[1]
+	}
+	return ""
+}
+
 // WrapAccessLog takes the cookie secret and a http.Handler, and returns a HandlerFunc which writes to the Access Log (which is the lib/go-log EventLog) after the HandlerFunc finishes.
 // This is not a Middleware, because it needs the secret as a parameter. For a Middleware, see GetWrapAccessLog.
 func WrapAccessLog(secret string, h http.Handler) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		var imsType = NONIMS
 		iw := &util.Interceptor{W: w}
 		user := "-"
-		cookie, err := r.Cookie(tocookie.Name)
-		if err == nil && cookie != nil {
-			cookie, userErr, sysErr := tocookie.Parse(secret, cookie.Value)
-			if userErr == nil && sysErr == nil {
-				user = cookie.AuthData
-			}
+		cookieToken := getCookieToken(r)
+		cookie, userErr, sysErr := tocookie.Parse(secret, cookieToken)
+		if userErr == nil && sysErr == nil {
+			user = cookie.AuthData
+		} else {
+			log.Errorf("Error retrieving user from cookie: User Error: %v System Error: %v", userErr, sysErr)
 		}
 		start := time.Now()
 		defer func() {

traffic_ops/traffic_ops_golang/routing/middleware/wrappers_test.go

@@ -440,4 +440,36 @@ func TestNoOpWhenNoPermissionsRequired(t *testing.T) {
 	}
 }
 
-// TODO: TestWrapAccessLog, et. al
+func TestGetCookieToken(t *testing.T) {
+	var cookies []http.Cookie
+	var e bytes.Buffer
+
+	mojoCookie := http.Cookie{Name: "mojolicious", Value: "eyJhdXRoX2RhdGEiOiJhZG1pbiIsImV4cGlyZXMiOjE2NzQyNTY4MjEsImJ5IjoidHJhZmZpY2NvbnRyb2wtZ28tdG9jb29raWUifQ--f7f40f516bfedc888d0ac6bc3c373b21773d1765"}
+	accessToken := http.Cookie{Name: "access_token", Value: "eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJleHAiOjE2NzQyNTY4MjEsIm1vam9Db29raWUiOiJleUpoZFhSb1gyUmhkR0VpT2lKaFpHMXBiaUlzSW1WNGNHbHlaWE1pT2pFMk56UXlOVFk0TWpFc0ltSjVJam9pZEhKaFptWnBZMk52Ym5SeWIyd3RaMjh0ZEc5amIyOXJhV1VpZlEtLWY3ZjQwZjUxNmJmZWRjODg4ZDBhYzZiYzNjMzczYjIxNzczZDE3NjUifQ.41te1VWlSzHCiH77nZjdqtGQNgc-ad6HwRi5cyffTGc"}
+	bearerToken := "Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJleHAiOjE2NzQ1MjU0OTcsIm1vam9Db29raWUiOiJleUpoZFhSb1gyUmhkR0VpT2lKaFpHMXBiaUlzSW1WNGNHbHlaWE1pT2pFMk56UTFNalUwT1Rjc0ltSjVJam9pZEhKaFptWnBZMk52Ym5SeWIyd3RaMjh0ZEc5amIyOXJhV1VpZlEtLTlmODI1Yzk5MDJhYTU5NDI1ZTQwYzJhYzcyNjhiZTI4NDMyMTg4ZjEifQ.szYraBtmKQ0UB13G6C3WUDcix1kZQyn4uqv27qy0_vY"
+	cookies = append(cookies, mojoCookie, accessToken, http.Cookie{})
+
+	r, err := http.NewRequest("GET", "https://localhost:8888", nil)
+	if err == nil && r != nil {
+		for i := range cookies {
+			if cookies[i].Name != "" {
+				r.AddCookie(&cookies[i])
+				cookie := getCookieToken(r)
+				if cookie != mojoCookie.Value && cookies[i].Name == "mojolicious" {
+					e.WriteString("Error: Unable to get mojolicious cookie. ")
+				} else if cookie != mojoCookie.Value && cookies[i].Name == "access_token" {
+					e.WriteString("Error: Unable to get mojolicious cookie from Access Token. ")
+				}
+			} else {
+				r.Header.Add("Authorization", bearerToken)
+				cookie := getCookieToken(r)
+				if cookie != mojoCookie.Value {
+					e.WriteString("Error: Unable to get cookie from Bearer Token.")
+				}
+			}
+		}
+	}
+	if e.String() != "" {
+		t.Error(e.String())
+	}
+}

traffic_ops/traffic_ops_golang/tocookie/cookie.go

@@ -26,6 +26,9 @@ import (
 
 const GeneratedByStr = "trafficcontrol-go-tocookie"
 const Name = "mojolicious"
+const MojoCookie = "mojoCookie"
+const AccessToken = "access_token"
+const BearerToken = "Bearer"
 const DefaultDuration = time.Hour
 
 type Cookie struct {