Enhanced auth-related logging

markdicksonjr · Feb 11, 2020 · b90116d · b90116d
1 parent 7ebf566
commit b90116d
Show file tree

Hide file tree

Showing 4 changed files with 14 additions and 1 deletion.
diff --git a/go.sum b/go.sum
@@ -108,6 +108,7 @@ github.com/go-cmd/cmd v1.0.5/go.mod h1:y8q8qlK5wQibcw63djSl/ntiHUHXHGdCkPk0j4QeW
 github.com/go-errors/errors v1.0.1/go.mod h1:f4zRHt4oKfwPJE5k8C9vpYG+aDHdBFUsgrm6/TyX73Q=
 github.com/go-ini/ini v1.44.0/go.mod h1:ByCAeIL28uOIIG0E3PJtZPDL8WnHpFKFOtgjp+3Ies8=
 github.com/go-kit/kit v0.8.0/go.mod h1:xBxKIO96dXMWWy0MnWVtmwkA9/13aqxPnvrjFYMA2as=
+github.com/go-log/log v0.1.0 h1:wudGTNsiGzrD5ZjgIkVZ517ugi2XRe9Q/xRCzwEO4/U=
 github.com/go-log/log v0.1.0/go.mod h1:4mBwpdRMFLiuXZDCwU2lKQFsoSCo72j3HqBK9d81N2M=
 github.com/go-logfmt/logfmt v0.3.0/go.mod h1:Qt1PoO58o5twSAckw1HlFXLmHsOX5/0LbT9GBnD5lWE=
 github.com/go-logfmt/logfmt v0.4.0/go.mod h1:3RMwSq7FuexP4Kalkev3ejPJsZTpXXBr9+V4qmtdjCk=

diff --git a/user/auth/local/extension.go b/user/auth/local/extension.go
@@ -116,6 +116,7 @@ func (s *Extension) GetName() string {
 func (s *Extension) GetCurrentUserHandler(w http.ResponseWriter, r *http.Request) {
 	currentUser, err := s.SessionExtension.GetCaller(r)
 	if err != nil {
+		s.app.Logger.Error("while getting user from session, error = " + err.Error())
 		nibbler.Write500Json(w, err.Error())
 		return
 	}
@@ -129,6 +130,7 @@ func (s *Extension) GetCurrentUserHandler(w http.ResponseWriter, r *http.Request
 	jsonString, err := user.ToJson(&safeUser)
 
 	if err != nil {
+		s.app.Logger.Error("while converting user to JSON from session, error = " + err.Error())
 		nibbler.Write500Json(w, err.Error())
 		return
 	}

diff --git a/user/auth/local/login.go b/user/auth/local/login.go
@@ -119,6 +119,7 @@ func (s *Extension) LogoutHandler(w http.ResponseWriter, r *http.Request) {
 func (s *Extension) Login(email string, password string) (*nibbler.User, error) {
 	u, err := s.UserExtension.GetUserByEmail(email)
 	if err != nil {
+		s.app.Logger.Error("while looking up user by email, error = " + err.Error())
 		return u, err
 	}
 
@@ -128,15 +129,18 @@ func (s *Extension) Login(email string, password string) (*nibbler.User, error)
 
 	validPassword, err := ValidatePassword(password, *u.Password)
 	if err != nil {
+		s.app.Logger.Error("while validating password in login flow, error = " + err.Error())
 		return nil, err
 	}
 
 	if !validPassword {
+		s.app.Logger.Trace("invalid password for email " + email)
 		return nil, errors.New("invalid password")
 	}
 
 	// if we need email verification but it hasn't been done yet, fail
 	if s.EmailVerificationEnabled && s.EmailVerificationRequired && (u.IsEmailValidated == nil || !*u.IsEmailValidated) {
+		s.app.Logger.Debug("login blocked for email " + email + " because it was not verified")
 		return nil, errors.New("email not verified")
 	}
 

diff --git a/user/auth/local/registration.go b/user/auth/local/registration.go
@@ -139,13 +139,15 @@ func (s *Extension) EmailTokenVerifyHandler(w http.ResponseWriter, r *http.Reque
 
 	// the endpoint is only available if verification is enabled
 	if !s.EmailVerificationEnabled {
+		s.app.Logger.Warn("got email token verification request while feature disabled")
 		nibbler.Write404Json(w)
 		return
 	}
 
 	// grab and validate input parameters
 	token := r.FormValue("token")
 	if token == "" {
+		s.app.Logger.Warn("got email token verification request with no token")
 		nibbler.Write500Json(w, "a token form parameter is required")
 		return
 	}
@@ -155,13 +157,14 @@ func (s *Extension) EmailTokenVerifyHandler(w http.ResponseWriter, r *http.Reque
 
 	// if an error happened during the lookup
 	if err != nil {
-		s.app.Logger.Error("while verifying email token: " + err.Error())
+		s.app.Logger.Error("while verifying email token, error = " + err.Error())
 		nibbler.Write200Json(w, `{"result": false}`)
 		return
 	}
 
 	// if no user has that email token
 	if userValue == nil {
+		s.app.Logger.Error("while verifying email token, user not found for validation token")
 		nibbler.Write200Json(w, `{"result": false}`)
 		return
 	}
@@ -172,6 +175,7 @@ func (s *Extension) EmailTokenVerifyHandler(w http.ResponseWriter, r *http.Reque
 	userValue.EmailValidationToken = nil
 	userValue.EmailValidationExpiration = nil
 	if err = s.UserExtension.Update(userValue); err != nil {
+		s.app.Logger.Error("failed to update user to mark success during email verification")
 		nibbler.Write500Json(w, err.Error())
 		return
 	}
@@ -181,6 +185,7 @@ func (s *Extension) EmailTokenVerifyHandler(w http.ResponseWriter, r *http.Reque
 	// more likely happen while not logged in
 	sessionUser, err := s.SessionExtension.GetCaller(r)
 	if err != nil {
+		s.app.Logger.Error("failed to get caller from session during email verification")
 		nibbler.Write500Json(w, err.Error())
 		return
 	}
@@ -190,6 +195,7 @@ func (s *Extension) EmailTokenVerifyHandler(w http.ResponseWriter, r *http.Reque
 		sessionUser.IsEmailValidated = &isTrue
 
 		if err := s.SessionExtension.SetCaller(w, r, sessionUser); err != nil {
+			s.app.Logger.Error("failed to set caller in session to update flag during email verification")
 			nibbler.Write500Json(w, err.Error())
 			return
 		}