diff --git a/handlers/google_auth.go b/handlers/google_auth.go index f339540..4d02254 100644 --- a/handlers/google_auth.go +++ b/handlers/google_auth.go @@ -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 } diff --git a/handlers/jwt.go b/handlers/jwt.go index 5d94fe8..b733688 100644 --- a/handlers/jwt.go +++ b/handlers/jwt.go @@ -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