Stop cleanly when Apple takes a code and then fails anyway

python/exporter/asyncui.py

@@ -43,6 +43,29 @@ class Asker:
     def __init__(self, root: tk.Misc) -> None:
         self._root = root
         self._cancelled = threading.Event()
+        self._say: Callable[[str], None] | None = None
+
+    def attach_status(self, say: Callable[[str], None]) -> None:
+        """Wire `say` to the progress window's label. Called by :func:`run_with_progress`."""
+        self._say = say
+
+    def say(self, text: str) -> None:
+        """
+        Change what the progress window says, from the worker thread.
+
+        **A window that has said "Signing in to iCloud…" for a minute is indistinguishable from a
+        hung one**, and that matters here because waiting is now something this deliberately does:
+        after Apple takes a verification code and then fails, the recovery is to wait and ask for
+        a new one. A silent minute in the middle of a sign-in is exactly when somebody force-quits.
+
+        Unlike :meth:`ask` this does not block and does not raise when cancelled - it is a status
+        line, and a caller should not have to handle a window closing to write to one.
+        """
+        if self._say is None or self._cancelled.is_set():
+            return
+
+        say = self._say
+        self._root.after(0, lambda: say(text))
 
     def cancel(self) -> None:
         """
@@ -102,8 +125,12 @@ def run_with_progress(
     :raises Exception: Whatever the coroutine raised, on the main thread, so a caller can report it
         the way it would report any other failure.
     """
-    window = _progress_window(root, message)
+    window, label = _progress_window(root, message)
     asker = Asker(root)
+
+    # So the worker can say what it is doing, rather than leaving one sentence up for a minute.
+    # Guarded on the widget still existing: the worker keeps going after the window is closed.
+    asker.attach_status(_status_setter(label))
     outcome: queue.Queue = queue.Queue(maxsize=1)
 
     def _work() -> None:
@@ -154,8 +181,28 @@ def _poll() -> None:
     return value
 
 
-def _progress_window(root: tk.Tk, message: str) -> tk.Toplevel:
-    """A small modal window with an indeterminate bar, since none of this reports progress."""
+def _status_setter(label: ttk.Label) -> Callable[[str], None]:
+    """
+    Rewrite the progress window's line, or do nothing once it has gone.
+
+    Its own function rather than a closure inside `run_with_progress`, which flake8 already
+    considers as branchy as it is allowed to get - and the guard is the interesting part: the
+    worker keeps running after the user closes the window, so this is called on a dead widget in
+    the ordinary course of cancelling.
+    """
+    def say(text: str) -> None:
+        if label.winfo_exists():
+            label.configure(text=text)
+
+    return say
+
+
+def _progress_window(root: tk.Tk, message: str) -> tuple[tk.Toplevel, ttk.Label]:
+    """
+    A small modal window with an indeterminate bar, since none of this reports progress.
+
+    Returns the label as well as the window so the worker can rewrite it - see :meth:`Asker.say`.
+    """
     window = tk.Toplevel(root)
     window.title("Working")
     window.resizable(width=False, height=False)
@@ -164,7 +211,8 @@ def _progress_window(root: tk.Tk, message: str) -> tk.Toplevel:
     frame = ttk.Frame(window, padding=16)
     frame.pack(fill="both", expand=True)
 
-    ttk.Label(frame, text=message, wraplength=320).pack(pady=(0, 12))
+    label = ttk.Label(frame, text=message, wraplength=320)
+    label.pack(pady=(0, 12))
 
     bar = ttk.Progressbar(frame, mode="indeterminate", length=320)
     bar.pack()
@@ -174,4 +222,4 @@ def _progress_window(root: tk.Tk, message: str) -> tk.Toplevel:
     window.grab_set()
     window.update_idletasks()
 
-    return window
+    return window, label

python/exporter/cli.py

@@ -340,6 +340,24 @@ async def _retry_credentials(error, attempt: int):
     return email, await prompts.password("Password")
 
 
+_said = ""
+
+
+def _say(text: str) -> None:
+    """
+    Report what the sign-in is waiting for, on one line that rewrites itself.
+
+    `\r` and no newline, so a countdown does not produce forty lines of scrollback - and to
+    stderr, which is where everything else conversational here goes. A redirected stderr gets the
+    carriage returns and is none the worse for it.
+    """
+    global _said
+
+    padding = max(0, len(_said) - len(text))
+    print(f"\r{text}{' ' * padding}", end="", file=sys.stderr, flush=True)
+    _said = text
+
+
 async def _retry_code(error, attempt: int):
     """
     Offer the verification code again, and only send a new one if asked.
@@ -489,6 +507,9 @@ async def sign_in(arguments: argparse.Namespace):
                 get_code=_ask_verification_code,
                 retry_credentials=_retry_credentials,
                 retry_code=_retry_code,
+                # The CLI has no window to look hung, but a silent three-quarters of a minute
+                # after a code was entered reads as a stuck program just as well.
+                announce=_say,
             )
         except MobileMeDelegateError as e:
             # Authentication itself worked; the exchange that follows it did not. Unaccepted terms

python/exporter/icloud.py

@@ -17,6 +17,7 @@
 
 from __future__ import annotations
 
+import asyncio
 import base64
 import logging
 import uuid
@@ -35,6 +36,7 @@
     SmsSecondFactorMethod,
     TrustedDeviceSecondFactorMethod,
 )
+from findmy.errors import UnhandledProtocolError
 from findmy.accessory import _extract_serial_from_stable_id  # noqa: PLC2701 - see _candidate
 from findmy.cloudkit.beacons import (
     AsyncBeaconStore,
@@ -341,6 +343,25 @@ def remember(account: AsyncAppleAccount, identity_path: Path | None = None) -> N
 """
 
 MAX_CODE_ATTEMPTS = 3
+
+# How long to wait before asking Apple for a new verification code, after it took the last one and
+# then failed on the re-authentication behind it (issue #168). One entry per retry.
+#
+# **The one recovery anyone has observed puts a floor under this, and it is higher than it looks.**
+# The sequence was: 503 after the code; then a whole manual round - re-typing the Apple ID and
+# password, choosing a delivery method, waiting for the code, typing it - which was refused at the
+# *password* step; then another round, which worked. A manual round is the better part of a minute,
+# so **roughly a minute after the 503 the account was still being refused**, and the thing that
+# eventually worked was about two rounds out. That is why the first wait is not thirty seconds.
+#
+# Strictly, the refusal in the middle was on the password call rather than the 2FA call, so it does
+# not *prove* a new code would have been rejected at that moment. It is the only measurement there
+# is, and it points one way.
+#
+# Two entries rather than one long wait, because the first is cheap and might be enough, and
+# because a single three-minute pause is indistinguishable from a hang however loudly it counts
+# down. Together they bracket the recovery that was actually seen.
+SPENT_CODE_WAITS = (60, 120)
 """How many times a verification code may be submitted before the sign-in is given up on."""
 
 CODE_AGAIN = "again"
@@ -365,6 +386,7 @@ async def log_in(
     get_code: Callable[[], Awaitable[str]],
     retry_credentials: Callable[[Exception, int], Awaitable[tuple[str, str] | None]] | None = None,
     retry_code: Callable[[Exception, int], Awaitable[str | None]] | None = None,
+    announce: Callable[[str], None] | None = None,
 ) -> None:
     """
     Sign in, dealing with two-factor authentication if the account asks for it.
@@ -378,8 +400,13 @@ async def log_in(
     :param get_code: Returns the code the user received. Awaited, as above.
     :param retry_credentials: Awaited with the error and the attempt number when Apple rejects the
         Apple ID or password; returns a replacement pair, or None to stop. None means one attempt.
-    :param retry_code: Awaited with the error and the attempt number when Apple rejects the
-        verification code; returns :data:`CODE_AGAIN`, :data:`CODE_RESEND`, or None to stop.
+    :param retry_code: Awaited with the error and the attempt number when submitting the
+        verification code fails; returns :data:`CODE_AGAIN`, :data:`CODE_RESEND`, or None to stop.
+        Ask :func:`code_was_already_spent` about the error before offering to re-type it - a
+        spent code is not offered to it at all.
+    :param announce: Called with a line of status while this waits out a fault on Apple's side.
+        Not awaited, and never required: it exists so a window can stop looking hung. See
+        :func:`_wait_then_send_a_new_code`.
     :raises ExportSourceError: If signing in does not end signed in.
     :raises InvalidCredentialsError: If the last attempt is rejected, or the user stops.
     """
@@ -394,7 +421,7 @@ async def log_in(
 
         chosen = methods[await choose_second_factor([_describe_factor(m) for m in methods])]
         await chosen.request()
-        state = await _submit_code_with_retries(chosen, get_code, retry_code)
+        state = await _submit_code_with_retries(chosen, get_code, retry_code, announce)
 
     if state != LoginState.LOGGED_IN:
         raise ExportSourceError(f"Signing in ended at {state} rather than signed in.")
@@ -428,18 +455,67 @@ async def _log_in_with_retries(account, email, password, retry_credentials):
     raise AssertionError("unreachable")  # pragma: no cover
 
 
-async def _submit_code_with_retries(chosen, get_code, retry_code):
+class SignInInterrupted(ExportSourceError):
+    """
+    Signing in stopped part-way through, for a reason that is Apple's rather than the user's.
+
+    **An `ExportSourceError` so nothing has to change to handle it**, and a distinct type so the
+    wizard can title the dialog truthfully. Its generic handler says "Could not read your
+    accessories", which is right for most of what `_load` raises and wrong for this: nothing was
+    read, because signing in never finished. A dialog that misdescribes what happened is worse
+    than a vague one - the reader corrects for it and then trusts the rest of it less.
+    """
+
+
+def code_was_already_spent(error: BaseException) -> bool:
+    """
+    Whether Apple took the verification code and then failed anyway.
+
+    **`td_2fa_submit` does two things, and only the second one failed.** It submits the code, and
+    then runs a full Grand Slam re-authentication behind it. Issue #168's log shows the first half
+    succeeding - "Attempting authentication for user" appears twice, and only `_gsa_authenticate`
+    logs that - and the second answering 503 half a second later.
+
+    That matters because it is the opposite of a rejected code. A rejected code is still live and
+    should be re-typed; this one has been consumed by the half that worked, so re-typing it is a
+    guaranteed second failure.
+
+    The net is wide - `UnhandledProtocolError` is FindMy.py's "Apple said something this library
+    does not model" - but every failure it catches here happened *after* the submit returned, so
+    the code is gone in all of them.
+    """
+    return isinstance(error, UnhandledProtocolError)
+
+
+async def _submit_code_with_retries(chosen, get_code, retry_code, announce=None):
     """
     Submit the verification code, letting a mistyped one be corrected.
 
     **The default retry re-types the code rather than asking for a new one**, and the difference is
     not cosmetic: requesting delivery again sends a second code *and invalidates the first*
     (findmy-export 01-authentication §5). So somebody who mistyped a code they are still holding
     would lose it by being "helpfully" sent another, and a resend has to be a thing they choose.
+
+    **A code Apple took and then failed on is not re-typed and is not asked about**: it waits and
+    sends a new one by itself. Nothing the user could type would help - the code is spent - and the
+    only recovery anyone has observed is the passage of time. Asking "shall I try again?" of
+    somebody with no way to judge the answer is a worse interface than doing it.
+
+    Bounded by the same attempt budget as a mistyped code, so the worst case is two waits and then
+    the message in :func:`_apple_failed_after_taking_the_code`.
     """
     for attempt in range(1, MAX_CODE_ATTEMPTS + 1):
         try:
             return await chosen.submit(await get_code())
+        except UnhandledProtocolError as e:
+            logger.info("Apple took the code and then failed to finish signing in: %s", e)
+
+            # The last attempt has nothing left to wait for, and waiting before saying so would
+            # only add a minute to a failure that has already happened.
+            if attempt == MAX_CODE_ATTEMPTS:
+                raise _apple_failed_after_taking_the_code(e) from e
+
+            await _wait_then_send_a_new_code(chosen, SPENT_CODE_WAITS[attempt - 1], announce)
         except InvalidCredentialsError as e:
             logger.info("Apple rejected the verification code on attempt %d", attempt)
 
@@ -458,6 +534,66 @@ async def _submit_code_with_retries(chosen, get_code, retry_code):
     raise AssertionError("unreachable")  # pragma: no cover
 
 
+async def _wait_then_send_a_new_code(chosen, seconds: int, announce=None) -> None:
+    """
+    Sit out Apple's bad minute, then ask for a fresh verification code.
+
+    **Counting down out loud, because the alternative is a window that looks hung.** Three quarters
+    of a minute of silence in the middle of a sign-in is when somebody force-quits, and this is a
+    deliberate wait rather than a slow call - so it says so, every second, and the progress window
+    keeps moving.
+
+    `announce` is optional so the retry logic stays testable without a front end; a caller that
+    passes nothing simply waits.
+    """
+    for remaining in range(seconds, 0, -1):
+        if announce is not None:
+            announce(
+                "Apple accepted the code and then had a problem finishing. That clears on its"
+                f" own - waiting {remaining}s, then sending a new code…",
+            )
+        await asyncio.sleep(1)
+
+    if announce is not None:
+        announce("Asking Apple for a new verification code…")
+
+    # Only now, because a code requested before the wait would be ageing throughout it - and
+    # Apple's codes expire. See findmy-export 01-authentication §5.
+    await chosen.request()
+
+
+def _apple_failed_after_taking_the_code(error: BaseException) -> SignInInterrupted:
+    """
+    What to tell somebody whose code was accepted and whose sign-in failed anyway.
+
+    **Nothing is offered, and that is the finding rather than a shrug.** Three recoveries were
+    available and only one is known to work:
+
+    - *Re-type the code.* Cannot work - it has been spent. Ruled out by what the failure is.
+    - *Send a new code immediately.* Not enough on its own. The sign-in that followed #168's 503
+      was refused at the *password* step, so whatever was unhappy stayed unhappy for longer than
+      one call.
+    - *Wait, then send a new code.* What :func:`_wait_then_send_a_new_code` now does, and what the
+      only successful recovery amounted to. This message is what is left when that has been tried
+      and has not worked.
+
+    So it says that, and stops. **An `ExportSourceError` rather than the protocol error it came
+    from**, because both front ends already show one of those as a plain message with no invitation
+    to report a bug - which is the entire complaint. `from e` keeps the status code in the log,
+    where it is the whole diagnosis if this ever turns out to be more than weather.
+    """
+    return SignInInterrupted(
+        f"Apple accepted your verification code and then failed to finish signing in: {error}\n\n"
+        "This is a fault on Apple's side rather than anything you did, and it clears on its own."
+        " Nothing was changed and nothing was sent.\n\n"
+        f"It was given {len(SPENT_CODE_WAITS)} chances to settle - waiting"
+        f" {' and then '.join(f'{s}s' for s in SPENT_CODE_WAITS)} - and did not.\n\n"
+        "Leave it a few minutes and sign in again. Apple may also refuse the password once while"
+        " it settles - that is part of the same hiccup rather than a second problem, and trying"
+        " once more is the answer.",
+    )
+
+
 def _describe_factor(method: object) -> str:
     """Name one second-factor method for a person choosing between them."""
     if isinstance(method, TrustedDeviceSecondFactorMethod):

python/exporter/wizard.py

@@ -366,6 +366,13 @@ def _load(self) -> None:
             )
             self.destroy()
             return
+        except icloud.SignInInterrupted as e:
+            # **Before the handler below, only for its title.** Nothing was read here, because
+            # signing in never finished - and "Could not read your accessories" over the top of a
+            # message about a verification code is the kind of wrong heading a reader corrects
+            # for and then trusts the rest of less.
+            messagebox.showerror("Could not finish signing in", str(e))
+            return
         except (ExportSourceError, ExportError) as e:
             messagebox.showerror("Could not read your accessories", str(e))
             return
@@ -461,6 +468,10 @@ async def _read_icloud(self, asker: Asker):
                     retry_credentials=lambda error, attempt: _async(
                         _ask_again_for_credentials(self, asker, error, attempt),
                     ),
+                    # So the progress window says what it is waiting for. Without this the wait
+                    # after a spent code is three quarters of a minute of "Signing in to iCloud…",
+                    # which is what a hang looks like.
+                    announce=asker.say,
                     retry_code=lambda error, attempt: _async(
                         _ask_again_for_code(self, asker, error, attempt),
                     ),