From 8e02154bf566a722bde287e4a8697147b3fc2997 Mon Sep 17 00:00:00 2001 From: Maycon Santos Date: Fri, 10 Jul 2026 16:11:27 +0200 Subject: [PATCH] [client] Add SSO login flow timing instrumentation (#6717) Users reported long delays between finishing browser authentication and the client connecting. Logs could not attribute the time: the PKCE and device flows were silent between issuing the auth URL and returning the token, and nothing recorded when the GUI issued the Up request after WaitSSOLogin completed. Add log lines covering the full chain: PKCE callback arrival and token exchange duration, device-flow polling and approval timing, GUI-side brackets around WaitSSOLogin and Up, daemon-side Up arrival and WaitSSOLogin return, and a frontend stall detector that reports when webview timers were suspended (macOS App Nap / hidden-window throttling), which delays the WaitSSOLogin-to-Up handoff. --- client/internal/auth/device_flow.go | 9 +++++++ client/internal/auth/pkce_flow.go | 12 ++++++++- client/server/server.go | 2 ++ client/ui/frontend/src/app.tsx | 3 +++ client/ui/frontend/src/lib/stallwatch.ts | 31 ++++++++++++++++++++++++ client/ui/services/connection.go | 4 +++ 6 files changed, 60 insertions(+), 1 deletion(-) create mode 100644 client/ui/frontend/src/lib/stallwatch.ts diff --git a/client/internal/auth/device_flow.go b/client/internal/auth/device_flow.go index e33765300..8d90fb82f 100644 --- a/client/internal/auth/device_flow.go +++ b/client/internal/auth/device_flow.go @@ -259,12 +259,18 @@ func (d *DeviceAuthorizationFlow) WaitToken(ctx context.Context, info AuthFlowIn ticker := time.NewTicker(interval) defer ticker.Stop() + log.Infof("device flow: waiting for user authorization, polling token endpoint every %s, code expires in %s", interval, timeout) + + start := time.Now() + polls := 0 + for { select { case <-waitCtx.Done(): return TokenInfo{}, waitCtx.Err() case <-ticker.C: + polls++ tokenResponse, err := d.requestToken(info) if err != nil { return TokenInfo{}, fmt.Errorf("parsing token response failed with error: %v", err) @@ -272,10 +278,12 @@ func (d *DeviceAuthorizationFlow) WaitToken(ctx context.Context, info AuthFlowIn if tokenResponse.Error != "" { if tokenResponse.Error == "authorization_pending" { + log.Tracef("device flow: authorization still pending after poll %d", polls) continue } else if tokenResponse.Error == "slow_down" { interval += (3 * time.Second) ticker.Reset(interval) + log.Infof("device flow: IdP requested slow_down, polling interval increased to %s", interval) continue } @@ -296,6 +304,7 @@ func (d *DeviceAuthorizationFlow) WaitToken(ctx context.Context, info AuthFlowIn return TokenInfo{}, fmt.Errorf("validate access token failed with error: %v", err) } + log.Infof("device flow: user authorization confirmed after %d polls in %s", polls, time.Since(start).Round(time.Second)) return tokenInfo, err } } diff --git a/client/internal/auth/pkce_flow.go b/client/internal/auth/pkce_flow.go index 84fa8a214..d0df2b122 100644 --- a/client/internal/auth/pkce_flow.go +++ b/client/internal/auth/pkce_flow.go @@ -188,6 +188,8 @@ func (p *PKCEAuthorizationFlow) WaitToken(ctx context.Context, info AuthFlowInfo waitCtx, cancel := context.WithTimeout(ctx, timeout) defer cancel() + log.Infof("pkce flow: waiting for authorization callback on %s, timeout %s", p.oAuthConfig.RedirectURL, timeout) + tokenChan := make(chan *oauth2.Token, 1) errChan := make(chan error, 1) @@ -221,6 +223,7 @@ func (p *PKCEAuthorizationFlow) WaitToken(ctx context.Context, info AuthFlowInfo func (p *PKCEAuthorizationFlow) startServer(server *http.Server, tokenChan chan<- *oauth2.Token, errChan chan<- error) { mux := http.NewServeMux() mux.HandleFunc("/", func(w http.ResponseWriter, req *http.Request) { + log.Infof("pkce flow: received authorization callback from IdP") cert := p.providerConfig.ClientCertPair if cert != nil { tr := &http.Transport{ @@ -271,11 +274,18 @@ func (p *PKCEAuthorizationFlow) handleRequest(req *http.Request) (*oauth2.Token, return nil, fmt.Errorf("authentication failed: missing code") } - return p.oAuthConfig.Exchange( + exchangeStart := time.Now() + token, err := p.oAuthConfig.Exchange( req.Context(), code, oauth2.SetAuthURLParam("code_verifier", p.codeVerifier), ) + if err != nil { + return nil, err + } + + log.Infof("pkce flow: authorization code exchanged for token in %s", time.Since(exchangeStart).Round(time.Millisecond)) + return token, nil } func (p *PKCEAuthorizationFlow) parseOAuthToken(token *oauth2.Token) (TokenInfo, error) { diff --git a/client/server/server.go b/client/server/server.go index 363f716a9..46f9a6055 100644 --- a/client/server/server.go +++ b/client/server/server.go @@ -828,6 +828,7 @@ func (s *Server) WaitSSOLogin(callerCtx context.Context, msg *proto.WaitSSOLogin return nil, err } + log.Infof("SSO login flow finished, returning success to caller") return &proto.WaitSSOLoginResponse{ Email: tokenInfo.Email, }, nil @@ -835,6 +836,7 @@ func (s *Server) WaitSSOLogin(callerCtx context.Context, msg *proto.WaitSSOLogin // Up starts engine work in the daemon. func (s *Server) Up(callerCtx context.Context, msg *proto.UpRequest) (*proto.UpResponse, error) { + log.Infof("up request received") s.mutex.Lock() // clientRunning is the daemon-intent flag (set by previous Up/Start, cleared // by Down). connectionGoroutineRunning() reports whether the previous retry-loop diff --git a/client/ui/frontend/src/app.tsx b/client/ui/frontend/src/app.tsx index c7b12e538..7f1359510 100644 --- a/client/ui/frontend/src/app.tsx +++ b/client/ui/frontend/src/app.tsx @@ -16,10 +16,13 @@ import LoginWaitingForBrowserDialog from "@/modules/login/LoginWaitingForBrowser import { initI18n } from "@/lib/i18n"; import { initPlatform } from "@/lib/platform"; import { initLogForwarding } from "@/lib/logs"; +import { initStallWatch } from "@/lib/stallwatch"; // Must run first so even init-time logs reach the Go log pipeline. initLogForwarding(); +initStallWatch(); + welcome(); Promise.all([ diff --git a/client/ui/frontend/src/lib/stallwatch.ts b/client/ui/frontend/src/lib/stallwatch.ts new file mode 100644 index 000000000..aca7d75bb --- /dev/null +++ b/client/ui/frontend/src/lib/stallwatch.ts @@ -0,0 +1,31 @@ +// Detects webview suspension (macOS App Nap / hidden-window timer throttling). +// While the webview is suspended no JS runs at all, so detection happens on +// resume: a 1s interval measures wall-clock drift and reports how long timers +// were frozen. Silent unless a stall actually occurred; a stalled webview is +// what delays promise continuations such as the WaitSSOLogin → Up handoff. + +const INTERVAL_MS = 1000; +const STALL_THRESHOLD_MS = 5000; +const REPORT_COOLDOWN_MS = 60_000; + +let started = false; + +export function initStallWatch() { + if (started) return; + started = true; + + let last = Date.now(); + let lastReport = 0; + setInterval(() => { + const now = Date.now(); + const stall = now - last - INTERVAL_MS; + last = now; + if (stall < STALL_THRESHOLD_MS) return; + if (now - lastReport < REPORT_COOLDOWN_MS) return; + lastReport = now; + console.warn( + `webview timers were suspended for ${(stall / 1000).toFixed(1)}s ` + + `(App Nap / hidden-window throttling); pending UI work ran late`, + ); + }, INTERVAL_MS); +} diff --git a/client/ui/services/connection.go b/client/ui/services/connection.go index a23a526e6..8e7919af6 100644 --- a/client/ui/services/connection.go +++ b/client/ui/services/connection.go @@ -116,6 +116,7 @@ func (s *Connection) Login(ctx context.Context, p LoginParams) (LoginResult, err if err != nil { return LoginResult{}, s.classifyDaemonError(err) } + log.Infof("daemon login response received, needs SSO login: %v", resp.GetNeedsSSOLogin()) return LoginResult{ NeedsSSOLogin: resp.GetNeedsSSOLogin(), UserCode: resp.GetUserCode(), @@ -129,6 +130,7 @@ func (s *Connection) WaitSSOLogin(ctx context.Context, p WaitSSOParams) (string, if err != nil { return "", err } + log.Infof("waiting for SSO login to complete") resp, err := cli.WaitSSOLogin(ctx, &proto.WaitSSOLoginRequest{ UserCode: p.UserCode, Hostname: p.Hostname, @@ -136,6 +138,7 @@ func (s *Connection) WaitSSOLogin(ctx context.Context, p WaitSSOParams) (string, if err != nil { return "", s.classifyDaemonError(err) } + log.Infof("SSO login completed, daemon reported success") return resp.GetEmail(), nil } @@ -144,6 +147,7 @@ func (s *Connection) Up(ctx context.Context, p UpParams) error { if err != nil { return err } + log.Infof("sending up request to daemon") // Always async: status updates flow via SubscribeStatus. req := &proto.UpRequest{Async: true} if p.ProfileName != "" {