fix(garmin): startup tokenstore resume recovers after its 10s timeout

The background login thread now flips _auth_state to authenticated
itself when a slow tokenstore resume succeeds after the 10s wait --
previously its result landed in an abandoned private queue and the
docstring's promised late recovery never happened, leaving every
subsequent call failing until an explicit authenticate. Guarded to only
ever transition from unauthenticated, so an explicit authenticate/MFA
flow that took over meanwhile is never clobbered; the timeout branch no
longer re-writes the state (a redundant write that could race a success
at the boundary). Structured-log messages reworked alongside.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

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"

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
+    Garmin login can never block the caller indefinitely. On timeout the
-    out, the thread keeps running and will update _auth_state whenever it
+    triggering call fails ("Not authenticated"), but the thread keeps
-    eventually finishes (success or failure), just without wedging the
+    running and, if the login eventually succeeds, flips _auth_state to
-    whole subprocess unresponsive in the meantime.
+    "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 "
+            "startup_login(): hit the 10s timeout but still running in the "
-            "background and will update auth state whenever it finishes",
+            "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."}
+        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, "
+            "handle_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.",
         )
         _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.",
         }