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