add debug logs to the authentication flow (#272)

* add debug logs to the authentication flow

* address PR comments

Author: DiogoFerrao

internal/pkg/auth/service_account.go

@@ -72,6 +72,8 @@ func AuthenticateServiceAccount(p *print.Printer, rt http.RoundTripper) (email s
 		return "", fmt.Errorf("get email from access token: %w", err)
 	}
 
+	p.Debug(print.DebugLevel, "successfully authenticated service account %s", email)
+
 	authFields[SERVICE_ACCOUNT_EMAIL] = email
 
 	sessionExpiresAtUnix, err := getStartingSessionExpiresAtUnix()

internal/pkg/auth/user_login.go

@@ -13,6 +13,7 @@ import (
 	"os/exec"
 	"path/filepath"
 	"runtime"
+	"strconv"
 	"strings"
 	"time"
 
@@ -82,6 +83,7 @@ func AuthorizeUser(p *print.Printer, isReauthentication bool) error {
 	// Define a handler that will get the authorization code, call the token endpoint, and close the HTTP server
 	var errServer error
 	mux.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
+		p.Debug(print.DebugLevel, "received request from authentication server")
 		// Close the server only if there was an error
 		// Otherwise, it will redirect to the succesfull login page
 		defer func() {
@@ -98,19 +100,31 @@ func AuthorizeUser(p *print.Printer, isReauthentication bool) error {
 			return
 		}
 
+		p.Debug(print.DebugLevel, "trading authorization code for access and refresh tokens")
+
 		// Trade the authorization code and the code verifier for access and refresh tokens
 		accessToken, refreshToken, err := getUserAccessAndRefreshTokens(authDomain, clientId, codeVerifier, code, redirectURL)
 		if err != nil {
 			errServer = fmt.Errorf("retrieve tokens: %w", err)
 			return
 		}
 
+		p.Debug(print.DebugLevel, "received response from the authentication server")
+
 		sessionExpiresAtUnix, err := getStartingSessionExpiresAtUnix()
 		if err != nil {
 			errServer = fmt.Errorf("compute session expiration timestamp: %w", err)
 			return
 		}
 
+		sessionExpiresAtUnixInt, err := strconv.Atoi(sessionExpiresAtUnix)
+		if err != nil {
+			p.Debug(print.ErrorLevel, "parse session expiration value \"%s\": %s", sessionExpiresAtUnix, err)
+		} else {
+			sessionExpiresAt := time.Unix(int64(sessionExpiresAtUnixInt), 0)
+			p.Debug(print.DebugLevel, "session expires at %s", sessionExpiresAt)
+		}
+
 		err = SetAuthFlow(AUTH_FLOW_USER_TOKEN)
 		if err != nil {
 			errServer = fmt.Errorf("set auth flow type: %w", err)
@@ -123,6 +137,8 @@ func AuthorizeUser(p *print.Printer, isReauthentication bool) error {
 			return
 		}
 
+		p.Debug(print.DebugLevel, "user %s logged in successfully", email)
+
 		authFields := map[authFieldKey]string{
 			SESSION_EXPIRES_AT_UNIX: sessionExpiresAtUnix,
 			ACCESS_TOKEN:            accessToken,
@@ -137,6 +153,8 @@ func AuthorizeUser(p *print.Printer, isReauthentication bool) error {
 
 		// Redirect the user to the successful login page
 		loginSuccessURL := redirectURL + loginSuccessPath
+
+		p.Debug(print.DebugLevel, "redirecting browser to login successful page")
 		http.Redirect(w, r, loginSuccessURL, http.StatusSeeOther)
 	})
 
@@ -163,6 +181,9 @@ func AuthorizeUser(p *print.Printer, isReauthentication bool) error {
 		}
 	})
 
+	p.Debug(print.DebugLevel, "opening browser for authentication")
+	p.Debug(print.DebugLevel, "using authentication server on %s", authDomain)
+
 	// Open a browser window to the authorizationURL
 	err = openBrowser(authorizationURL)
 	if err != nil {
@@ -171,6 +192,7 @@ func AuthorizeUser(p *print.Printer, isReauthentication bool) error {
 
 	// Start the blocking web server loop
 	// It will exit when the handlers get fired and call server.Close()
+	p.Debug(print.DebugLevel, "listening for response from authentication server on %s", redirectURL)
 	err = server.Serve(listener)
 	if !errors.Is(err, http.ErrServerClosed) {
 		return fmt.Errorf("server for PKCE flow closed unexpectedly: %w", err)

internal/pkg/auth/user_token_flow.go

@@ -50,6 +50,7 @@ func (utf *userTokenFlow) RoundTrip(req *http.Request) (*http.Response, error) {
 	} else if refreshTokenExpired, err := tokenExpired(utf.refreshToken); err != nil {
 		return nil, fmt.Errorf("check if refresh token has expired: %w", err)
 	} else if !refreshTokenExpired {
+		utf.printer.Debug(print.DebugLevel, "access token expired, refreshing...")
 		err = refreshTokens(utf)
 		if err == nil {
 			accessTokenValid = true
@@ -59,6 +60,7 @@ func (utf *userTokenFlow) RoundTrip(req *http.Request) (*http.Response, error) {
 	}
 
 	if !accessTokenValid {
+		utf.printer.Debug(print.DebugLevel, "user access token is not valid, reauthenticating...")
 		err = reauthenticateUser(utf)
 		if err != nil {
 			return nil, fmt.Errorf("reauthenticate user: %w", err)