[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

@@ -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
 		}
 	}

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) {

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

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([

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);
+}

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 != "" {