diff --git a/backend/internal/garmin/wrapper/tests/test_wrapper.py b/backend/internal/garmin/wrapper/tests/test_wrapper.py index e99431e..b55d2c5 100644 --- a/backend/internal/garmin/wrapper/tests/test_wrapper.py +++ b/backend/internal/garmin/wrapper/tests/test_wrapper.py @@ -1,4 +1,5 @@ import os +import time import queue import threading from unittest.mock import MagicMock, patch @@ -302,3 +303,51 @@ def test_call_does_not_mark_other_errors_as_not_found(): assert resp["id"] == 12 assert resp["error"] == "rate limited" assert "not_found" not in resp + + +def test_startup_login_late_success_flips_auth_state_for_later_calls(): + """A tokenstore resume that outlives the 10s wait must still recover + the subprocess: the background thread itself flips _auth_state on + success, so the next `call` command passes the auth check without an + explicit authenticate.""" + env = {"GARMIN_EMAIL": "test@example.com", "GARMIN_PASSWORD": "secret"} + release = threading.Event() + mock_client = MagicMock() + mock_client.login.side_effect = lambda **kwargs: release.wait(timeout=5) + wrapper._auth_state = "unauthenticated" + with patch.dict("os.environ", env): + with patch("wrapper.Garmin", return_value=mock_client): + with patch("wrapper.queue.Queue") as mock_queue_cls: + # Simulate the 10s timeout: the reader gives up immediately, + # while the (still-blocked) login thread keeps running. + mock_queue_cls.return_value.get.side_effect = queue.Empty + wrapper._startup_login() + assert wrapper._auth_state == "unauthenticated" + + release.set() # the slow login now completes, after the timeout + for _ in range(100): + if wrapper._auth_state == "authenticated": + break + time.sleep(0.01) + assert wrapper._auth_state == "authenticated" + + +def test_startup_login_late_success_never_overrides_explicit_auth_flow(): + """If an explicit authenticate/MFA flow moved the state while the + startup resume was still in flight, the late success must not clobber + it -- the explicit flow owns the state once it has moved it.""" + env = {"GARMIN_EMAIL": "test@example.com", "GARMIN_PASSWORD": "secret"} + release = threading.Event() + mock_client = MagicMock() + mock_client.login.side_effect = lambda **kwargs: release.wait(timeout=5) + wrapper._auth_state = "unauthenticated" + with patch.dict("os.environ", env): + with patch("wrapper.Garmin", return_value=mock_client): + with patch("wrapper.queue.Queue") as mock_queue_cls: + mock_queue_cls.return_value.get.side_effect = queue.Empty + wrapper._startup_login() + + wrapper._auth_state = "mfa_pending" # an explicit flow took over meanwhile + release.set() + time.sleep(0.2) # give the thread ample time to (wrongly) flip it + assert wrapper._auth_state == "mfa_pending" diff --git a/backend/internal/garmin/wrapper/wrapper.py b/backend/internal/garmin/wrapper/wrapper.py index 0fcaf67..e223c85 100644 --- a/backend/internal/garmin/wrapper/wrapper.py +++ b/backend/internal/garmin/wrapper/wrapper.py @@ -36,9 +36,9 @@ def _log(level, msg, **attrs): def _prompt_mfa(): - _log("info", "garminconnect invoked prompt_mfa() -- this is a REAL MFA challenge from Garmin") + _log("debug", "prompt_mfa(): invoked") code = _mfa_input_queue.get(timeout=300) - _log("debug", "prompt_mfa() handing code back to garminconnect", code_length=len(code)) + _log("debug", "prompt_mfa(): returning MFA code", code_length=len(code)) return code @@ -61,10 +61,13 @@ def _startup_login(): Bounded to the same 10s timeout as _handle_authenticate: the actual login runs on a background daemon thread, and this function waits up to 10s for it before returning either way, so a slow/rate-limited - Garmin login can never block the caller indefinitely -- if it times - out, the thread keeps running and will update _auth_state whenever it - eventually finishes (success or failure), just without wedging the - whole subprocess unresponsive in the meantime. + Garmin login can never block the caller indefinitely. On timeout the + triggering call fails ("Not authenticated"), but the thread keeps + running and, if the login eventually succeeds, flips _auth_state to + "authenticated" itself -- only ever from "unauthenticated", never + overriding an explicit authenticate/MFA flow that ran in the + meantime -- so subsequent calls recover without user action. A late + failure changes nothing (the state is already "unauthenticated"). Deliberately uses its own private, function-local result queue rather than the module-level _login_result_queue that _handle_authenticate and @@ -76,6 +79,7 @@ def _startup_login(): unrelated, later authenticate/complete_mfa call instead of that call's own fresh result.""" global _client, _auth_state + email = os.environ.get("GARMIN_EMAIL") password = os.environ.get("GARMIN_PASSWORD") if not email or not password: @@ -85,28 +89,48 @@ def _startup_login(): result_queue = queue.Queue() # private to this call, never shared with authenticate/complete_mfa def _do_login(): + global _auth_state + _log("debug", "startup_login(): background thread starting _client.login()", tokenstore=TOKENSTORE) try: _client.login(tokenstore=TOKENSTORE) + _log("debug", "startup_login(): _client.login() returned successfully") result_queue.put(("success", None)) + # A success arriving after the 10s timeout below would land in + # an abandoned queue -- flip the state here too, so later calls + # benefit from the resume. Only from "unauthenticated": a + # concurrent explicit authenticate/MFA flow owns the state once + # it has moved it anywhere else. + if _auth_state == "unauthenticated": + _auth_state = "authenticated" except Exception as exc: + _log( + "error", + "startup_login(): _client.login() failed", + error=str(exc), + error_type=type(exc).__name__, + traceback=traceback.format_exc(), + ) result_queue.put(("error", str(exc))) threading.Thread(target=_do_login, daemon=True).start() try: status, err = result_queue.get(timeout=10) + _log("debug", "startup_login(): got result within 10s timeout", status=status) if status == "success": _auth_state = "authenticated" else: - _log("warn", "startup tokenstore login failed", error=err) + _log("error", "startup_login(): login failed", error=err) _auth_state = "unauthenticated" except queue.Empty: + # No assignment here: the state is already "unauthenticated", and + # writing it again could clobber a success the background thread + # records right around the timeout boundary (see _do_login). _log( "warn", - "startup tokenstore login hit the 10s timeout -- still running in the " - "background and will update auth state whenever it finishes", + "startup_login(): hit the 10s timeout but still running in the " + "background and will update auth state if it eventually succeeds", ) - _auth_state = "unauthenticated" def _handle_authenticate(_params): @@ -126,15 +150,15 @@ def _handle_authenticate(_params): } def _do_login(): - _log("debug", "background login thread starting _client.login()", tokenstore=TOKENSTORE) + _log("debug", "handle_authenticate(): background thread starting _client.login()", tokenstore=TOKENSTORE) try: _client.login(tokenstore=TOKENSTORE) - _log("debug", "_client.login() returned successfully") + _log("debug", "handle_authenticate(): _client.login() returned successfully") _login_result_queue.put(("success", None)) except Exception as exc: _log( "error", - "_client.login() raised", + "handle_authenticate(): _client.login() failed", error=str(exc), error_type=type(exc).__name__, traceback=traceback.format_exc(), @@ -147,18 +171,17 @@ def _handle_authenticate(_params): try: status, err = _login_result_queue.get(timeout=10) - _log("debug", "authenticate got result within 10s timeout", status=status) + _log("debug", "handle_authenticate(): got result within 10s timeout", status=status) if status == "success": _auth_state = "authenticated" return {"status": "success", "message": "Authenticated successfully."} - return {"status": "failed", "message": f"Authentication failed: {err}"} + else: + _log("error", "handle_authenticate(): login failed", error=err) + return {"status": "failed", "message": f"Authentication failed: {err}"} except queue.Empty: _log( "warn", - "authenticate hit the 10s timeout with no result yet -- reporting mfa_required, " - "but this does NOT necessarily mean prompt_mfa() was actually invoked; check " - "whether the 'REAL MFA challenge' log line above appears to tell real MFA " - "apart from a merely slow login.", + "handle_authenticate(): hit the 10s timeout with no result yet, reporting mfa_required", ) _auth_state = "mfa_pending" return { @@ -174,21 +197,25 @@ def _handle_complete_mfa(params): return {"status": "failed", "message": "No MFA in progress. Call authenticate first."} code = params["code"] - _log("debug", "complete_mfa received a code, pushing to mfa queue", code_length=len(code)) + _log("debug", "handle_complete_mfa(): received a code, pushing to mfa queue", code_length=len(code)) _mfa_input_queue.put(code) try: status, err = _login_result_queue.get(timeout=30) - _log("debug", "complete_mfa got result", status=status, error=err) + _log("debug", "handle_complete_mfa(): got result", status=status, error=err) if status == "success": _auth_state = "authenticated" return {"status": "success", "message": "MFA accepted. Authenticated successfully."} return {"status": "failed", "message": f"Authentication failed after MFA: {err}"} except queue.Empty: + _log( + "error", + "handle_complete_mfa(): hit the 30s timeout with no result yet, reporting unauthenticated", + ) _auth_state = "unauthenticated" return { "status": "failed", - "message": "Timed out waiting for authentication to complete. Call authenticate again.", + "message": "Timed out waiting for authentication to complete.", }