added project status in project metadata
This commit is contained in:
+32
-1
@@ -168,18 +168,26 @@ func getIPAddress(r *http.Request) string {
|
||||
}
|
||||
|
||||
func GoogleCallback(w http.ResponseWriter, r *http.Request) {
|
||||
callbackStart := time.Now()
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] callback start path=%s query=%s", r.URL.Path, r.URL.RawQuery))
|
||||
|
||||
ipAddress := getIPAddress(r)
|
||||
fmt.Printf("INFO: Extracted IP address: %s\n", ipAddress)
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] ip extraction done duration_ms=%d", time.Since(callbackStart).Milliseconds()))
|
||||
|
||||
userAgent := r.Header.Get("User-Agent")
|
||||
|
||||
stateStart := time.Now()
|
||||
if !validateState(w, r) {
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] state validation failed duration_ms=%d total_ms=%d", time.Since(stateStart).Milliseconds(), time.Since(callbackStart).Milliseconds()))
|
||||
return
|
||||
}
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] state validation ok duration_ms=%d", time.Since(stateStart).Milliseconds()))
|
||||
|
||||
googleUserInfoStart := time.Now()
|
||||
userInfo, err := FetchGoogleUserInfo(w, r)
|
||||
if err != nil {
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] fetch google userinfo failed duration_ms=%d total_ms=%d", time.Since(googleUserInfoStart).Milliseconds(), time.Since(callbackStart).Milliseconds()))
|
||||
errMsg := err.Error()
|
||||
helper.LogError(err, "Failed to fetch Google user info")
|
||||
|
||||
@@ -208,15 +216,19 @@ func GoogleCallback(w http.ResponseWriter, r *http.Request) {
|
||||
helper.RespondWithError(w, http.StatusBadGateway, "Failed to fetch user information from Google. Please try again.")
|
||||
return
|
||||
}
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] fetch google userinfo ok duration_ms=%d", time.Since(googleUserInfoStart).Milliseconds()))
|
||||
|
||||
email := userInfo.Email
|
||||
|
||||
emailCheckStart := time.Now()
|
||||
emailExists, err := checkEmailInDB(email)
|
||||
if err != nil {
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] email check failed duration_ms=%d total_ms=%d", time.Since(emailCheckStart).Milliseconds(), time.Since(callbackStart).Milliseconds()))
|
||||
helper.LogError(err, "Error checking email")
|
||||
helper.RespondWithError(w, http.StatusBadGateway, "Error checking email in database")
|
||||
return
|
||||
}
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] email check ok duration_ms=%d", time.Since(emailCheckStart).Milliseconds()))
|
||||
|
||||
if !emailExists {
|
||||
helper.LogError(errors.New("unregistered email"), "Google login attempt with unregistered email: "+email)
|
||||
@@ -243,10 +255,12 @@ func GoogleCallback(w http.ResponseWriter, r *http.Request) {
|
||||
|
||||
accessToken, refreshToken, err := GenerateTokens(email, userAgent, ipAddress)
|
||||
if err != nil {
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] token generation failed total_ms=%d", time.Since(callbackStart).Milliseconds()))
|
||||
helper.LogError(err, "Error generating access token")
|
||||
helper.RespondWithError(w, http.StatusInternalServerError, "Token generation failed")
|
||||
return
|
||||
}
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] token generation ok elapsed_ms=%d", time.Since(callbackStart).Milliseconds()))
|
||||
|
||||
var refreshTokenExpiry time.Duration
|
||||
if emailExists {
|
||||
@@ -285,21 +299,26 @@ func GoogleCallback(w http.ResponseWriter, r *http.Request) {
|
||||
|
||||
userID, err := services.GetUserID(email)
|
||||
if err != nil {
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] get user id failed total_ms=%d", time.Since(callbackStart).Milliseconds()))
|
||||
helper.LogError(err, "Error fetching user")
|
||||
helper.RespondWithError(w, http.StatusBadGateway, "Failed to fetch user information")
|
||||
return
|
||||
}
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] get user id ok total_ms=%d", time.Since(callbackStart).Milliseconds()))
|
||||
|
||||
// Dereference pointers to get actual string values
|
||||
|
||||
helper.LogInfo("Access Token Generated Copy this: " + accessToken)
|
||||
|
||||
loginLogStart := time.Now()
|
||||
err = helper.LogLoginEventV2(userID, ipAddress)
|
||||
if err != nil {
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] login event log failed duration_ms=%d total_ms=%d", time.Since(loginLogStart).Milliseconds(), time.Since(callbackStart).Milliseconds()))
|
||||
helper.LogError(err, fmt.Sprintf("Failed to log login event. user_id=%s ip=%s", userID, ipAddress))
|
||||
helper.RespondWithError(w, http.StatusBadGateway, "Failed to Log Login Event")
|
||||
return
|
||||
}
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] login event log ok duration_ms=%d", time.Since(loginLogStart).Milliseconds()))
|
||||
|
||||
helper.LogInfo("Copy this access token: " + accessToken)
|
||||
|
||||
@@ -314,12 +333,14 @@ func GoogleCallback(w http.ResponseWriter, r *http.Request) {
|
||||
}
|
||||
log.Print("Valid redirect_uri: ", RedirectURI)
|
||||
RedirectURL := fmt.Sprintf("%s/callback?token=%s&user_id=%s", RedirectURI, accessToken, userID)
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] callback complete redirect=true total_ms=%d", time.Since(callbackStart).Milliseconds()))
|
||||
http.Redirect(w, r, RedirectURL, http.StatusSeeOther)
|
||||
return
|
||||
}
|
||||
|
||||
log.Print("No redirect_uri provided, returning JSON response")
|
||||
// No redirect_uri provided, return JSON response
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] callback complete redirect=false total_ms=%d", time.Since(callbackStart).Milliseconds()))
|
||||
helper.RespondWithJSON(w, http.StatusOK, map[string]string{
|
||||
"message": "Authentication successful",
|
||||
"access_token": accessToken,
|
||||
@@ -347,13 +368,19 @@ func validateState(w http.ResponseWriter, r *http.Request) bool {
|
||||
}
|
||||
|
||||
func FetchGoogleUserInfo(w http.ResponseWriter, r *http.Request) (models.UserGoogleInfo, error) {
|
||||
fetchStart := time.Now()
|
||||
code := r.URL.Query().Get("code")
|
||||
log.Print("Authorization code received: ", code)
|
||||
token, err := googleOauthConfig.Exchange(context.Background(), code)
|
||||
exchangeStart := time.Now()
|
||||
exchangeCtx, exchangeCancel := context.WithTimeout(context.Background(), 10*time.Second)
|
||||
defer exchangeCancel()
|
||||
token, err := googleOauthConfig.Exchange(exchangeCtx, code)
|
||||
if err != nil {
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] google exchange failed duration_ms=%d total_ms=%d", time.Since(exchangeStart).Milliseconds(), time.Since(fetchStart).Milliseconds()))
|
||||
helper.LogError(err, "Error exchanging authorization code for token")
|
||||
return models.UserGoogleInfo{}, fmt.Errorf("failed to exchange authorization code: %w", err)
|
||||
}
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] google exchange ok duration_ms=%d", time.Since(exchangeStart).Milliseconds()))
|
||||
|
||||
helper.LogInfo(fmt.Sprintf("Access Token: %s", token.AccessToken))
|
||||
|
||||
@@ -372,6 +399,7 @@ func FetchGoogleUserInfo(w http.ResponseWriter, r *http.Request) (models.UserGoo
|
||||
|
||||
resp, err := client.Do(req)
|
||||
if err != nil {
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] google userinfo request failed duration_ms=%d total_ms=%d", time.Since(exchangeStart).Milliseconds(), time.Since(fetchStart).Milliseconds()))
|
||||
errMsg := fmt.Sprintf("Failed to fetch user info from Google: %v", err)
|
||||
helper.LogError(err, errMsg)
|
||||
|
||||
@@ -403,6 +431,7 @@ func FetchGoogleUserInfo(w http.ResponseWriter, r *http.Request) (models.UserGoo
|
||||
|
||||
// Check HTTP status code
|
||||
if resp.StatusCode != http.StatusOK {
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] google userinfo non-200 status=%d total_ms=%d", resp.StatusCode, time.Since(fetchStart).Milliseconds()))
|
||||
bodyBytes, _ := io.ReadAll(resp.Body)
|
||||
errMsg := fmt.Sprintf("Google API returned status %d: %s", resp.StatusCode, string(bodyBytes))
|
||||
helper.LogError(nil, errMsg)
|
||||
@@ -411,9 +440,11 @@ func FetchGoogleUserInfo(w http.ResponseWriter, r *http.Request) (models.UserGoo
|
||||
|
||||
var userInfo models.UserGoogleInfo
|
||||
if err := json.NewDecoder(resp.Body).Decode(&userInfo); err != nil {
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] google userinfo decode failed total_ms=%d", time.Since(fetchStart).Milliseconds()))
|
||||
helper.LogError(err, "Error decoding user info from Google response")
|
||||
return models.UserGoogleInfo{}, fmt.Errorf("failed to parse user info response: %w", err)
|
||||
}
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] fetch google userinfo complete total_ms=%d", time.Since(fetchStart).Milliseconds()))
|
||||
return userInfo, nil
|
||||
}
|
||||
|
||||
|
||||
+28
-3
@@ -86,22 +86,30 @@ func init() {
|
||||
//
|
||||
// Returns:
|
||||
func GenerateTokens(email, userAgent, ipAddress string) (string, string, error) {
|
||||
totalStart := time.Now()
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] GenerateTokens start email=%s", email))
|
||||
ctx := context.Background()
|
||||
|
||||
emailExistsStart := time.Now()
|
||||
emailExists, err := CheckEmailInDB(email)
|
||||
if err != nil {
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] GenerateTokens CheckEmailInDB failed duration_ms=%d", time.Since(emailExistsStart).Milliseconds()))
|
||||
return "", "", fmt.Errorf("error checking email in database: %w", err)
|
||||
}
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] GenerateTokens CheckEmailInDB ok duration_ms=%d", time.Since(emailExistsStart).Milliseconds()))
|
||||
|
||||
userIDLookupStart := time.Now()
|
||||
userID, err := services.GetUserIDFromEmail(email)
|
||||
if err != nil {
|
||||
userID = helper.UUIDGenerator()
|
||||
}
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] GenerateTokens GetUserIDFromEmail done duration_ms=%d", time.Since(userIDLookupStart).Milliseconds()))
|
||||
|
||||
log.Print("userID:", userID)
|
||||
|
||||
tokenEmail := email
|
||||
roleID := make([]int, 0)
|
||||
fetchUserStart := time.Now()
|
||||
user, err := services.FetchUserByEmail(email)
|
||||
if err != nil {
|
||||
helper.LogWarn(fmt.Sprintf("Failed to fetch user profile for JWT role mapping (%s): %v", email, err))
|
||||
@@ -114,6 +122,7 @@ func GenerateTokens(email, userAgent, ipAddress string) (string, string, error)
|
||||
}
|
||||
roleID = buildJWTClaimRoleIDs(user)
|
||||
}
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] GenerateTokens FetchUserByEmail done duration_ms=%d", time.Since(fetchUserStart).Milliseconds()))
|
||||
sessionID := helper.UUIDGenerator()
|
||||
|
||||
refreshToken, err := generateSecureToken()
|
||||
@@ -149,30 +158,46 @@ func GenerateTokens(email, userAgent, ipAddress string) (string, string, error)
|
||||
IsRevoked: false,
|
||||
}
|
||||
|
||||
_, err = db.DB.Exec(`
|
||||
dbInsertStart := time.Now()
|
||||
helper.LogInfo("[oauth-debug] GenerateTokens jwt_sessions insert start")
|
||||
dbInsertCtx, dbInsertCancel := context.WithTimeout(ctx, 3*time.Second)
|
||||
defer dbInsertCancel()
|
||||
_, err = db.DB.ExecContext(dbInsertCtx, `
|
||||
INSERT INTO jwt_sessions (jwt_sessions_id, user_id, refresh_token_hash, user_agent, ip_address, created_at, updated_at, expires_at, is_revoked)
|
||||
VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?)
|
||||
`, sessionID, userID, refreshTokenHash, userAgent, ipAddress, currentTime, currentTime, expiresAt, false)
|
||||
if err != nil {
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] GenerateTokens jwt_sessions insert failed duration_ms=%d", time.Since(dbInsertStart).Milliseconds()))
|
||||
return "", "", fmt.Errorf("failed to store session: %w", err)
|
||||
}
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] GenerateTokens jwt_sessions insert ok duration_ms=%d", time.Since(dbInsertStart).Milliseconds()))
|
||||
|
||||
sessionKey := fmt.Sprintf(redisKeyJWTSession, refreshTokenHash)
|
||||
sessionIDKey := fmt.Sprintf(redisKeyJWTSessionID, sessionID)
|
||||
sessionTTL := int(time.Until(expiresAt).Seconds())
|
||||
if sessionTTL > 0 {
|
||||
if err := helper.SetJSON(ctx, sessionKey, session, &sessionTTL); err != nil {
|
||||
redisStart := time.Now()
|
||||
helper.LogInfo("[oauth-debug] GenerateTokens redis cache start")
|
||||
redisCtx, redisCancel := context.WithTimeout(ctx, 2*time.Second)
|
||||
defer redisCancel()
|
||||
if err := helper.SetJSON(redisCtx, sessionKey, session, &sessionTTL); err != nil {
|
||||
helper.LogError(err, "Failed to cache session in Redis (sessionKey)")
|
||||
}
|
||||
if err := helper.SetJSON(ctx, sessionIDKey, session, &sessionTTL); err != nil {
|
||||
if err := helper.SetJSON(redisCtx, sessionIDKey, session, &sessionTTL); err != nil {
|
||||
helper.LogError(err, "Failed to cache session in Redis (sessionIDKey)")
|
||||
}
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] GenerateTokens redis cache done duration_ms=%d", time.Since(redisStart).Milliseconds()))
|
||||
}
|
||||
|
||||
signStart := time.Now()
|
||||
helper.LogInfo("[oauth-debug] GenerateTokens access token sign start")
|
||||
accessToken, err := generateAccessToken(tokenEmail, sessionID, userID, roleID)
|
||||
if err != nil {
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] GenerateTokens access token sign failed duration_ms=%d", time.Since(signStart).Milliseconds()))
|
||||
return "", "", fmt.Errorf(errFormatWithContext, errMsgFailedToGenerateAccessToken, err)
|
||||
}
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] GenerateTokens access token sign ok duration_ms=%d", time.Since(signStart).Milliseconds()))
|
||||
helper.LogInfo(fmt.Sprintf("[oauth-debug] GenerateTokens complete total_ms=%d", time.Since(totalStart).Milliseconds()))
|
||||
|
||||
log.Printf("Generated tokens for user %s with session %s", email, sessionID)
|
||||
return accessToken, refreshToken, nil
|
||||
|
||||
Reference in New Issue
Block a user