From e28c774222a297ae5f7c7ddc948228148afe3706 Mon Sep 17 00:00:00 2001 From: "Shane B." Date: Sun, 30 Aug 2026 21:37:47 +0200 Subject: [PATCH 1/2] Stop cleanly when Apple takes a code and then fails anyway Issue #168. Apple accepted a verification code and answered 503 to the re-authentication behind it, and the sign-in died in the wizard's catch-all handler - which names an exception type and links the issue tracker. So the one person who could do nothing about it was invited to file it, and one duly did. td_2fa_submit does two things: it submits the code, and then runs a full GSA re-authentication. The reported log shows the first half succeeding - "Attempting authentication for user" appears twice and only _gsa_authenticate logs that - and the second returning 503 half a second later. Reproduced independently since. **It never reached the retry offer**, because only InvalidCredentialsError was caught. That is the bug, and it is a messaging bug rather than a retrying one. Nothing is retried, and that is the finding. Three recoveries existed: - Re-type the code. Cannot work; the half that succeeded spent it. - Send a new code and carry on. **Untested.** Nobody has observed this recovering. The sign-in after the reproduced 503 was refused at the *password* step, which looks like Apple throttling the account or the machine identity for a while - and sending two more codes into that is how a throttle becomes a lock. - Start again shortly. What actually worked, both times. So it says that and stops, as an ExportSourceError rather than the protocol error it came from: 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. The message also warns that the next password attempt may be refused once, because that happened and would otherwise read as a second, unrelated fault. Seven tests. All verified failable: letting the protocol error escape unchanged turns four red, and retrying instead of stopping turns the same four red - including the one asserting retry_code is never consulted, which is what stops a later edit quietly offering the untested recovery. Not fixed here: the Android app reaches the same library and will show its "this one is a bug" page for the same 503, and FindMy.py still folds every non-OK status into UnhandledProtocolError, so nothing downstream can tell a 503 from an unmodelled response without reading the message. Co-Authored-By: Claude Opus 5 --- python/exporter/icloud.py | 63 +++++++++++++++++- python/test/test_retries.py | 125 ++++++++++++++++++++++++++++++++++++ 2 files changed, 186 insertions(+), 2 deletions(-) diff --git a/python/exporter/icloud.py b/python/exporter/icloud.py index fe9a804e..495e7678 100644 --- a/python/exporter/icloud.py +++ b/python/exporter/icloud.py @@ -35,6 +35,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, @@ -378,8 +379,9 @@ 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. :raises ExportSourceError: If signing in does not end signed in. :raises InvalidCredentialsError: If the last attempt is rejected, or the user stops. """ @@ -428,6 +430,26 @@ async def _log_in_with_retries(account, email, password, retry_credentials): raise AssertionError("unreachable") # pragma: no cover +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): """ Submit the verification code, letting a mistyped one be corrected. @@ -436,10 +458,17 @@ async def _submit_code_with_retries(chosen, get_code, retry_code): 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 stops instead of retrying**, and that is deliberate + rather than lazy - see :func:`code_was_already_spent` for what it is, and the message below for + why nothing is offered. """ 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) + raise _apple_failed_after_taking_the_code(e) from e except InvalidCredentialsError as e: logger.info("Apple rejected the verification code on attempt %d", attempt) @@ -458,6 +487,36 @@ async def _submit_code_with_retries(chosen, get_code, retry_code): raise AssertionError("unreachable") # pragma: no cover +def _apple_failed_after_taking_the_code(error: BaseException) -> ExportSourceError: + """ + 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 and carry on.* **Untested.** Nobody has observed this recovering, and the + one report that recovered did not do it. Worse, the sign-in that followed #168's 503 was + refused at the *password* step, which looks like Apple throttling the account or the machine + identity for a while - and requesting two more codes into that is how a throttle becomes a + lock. Rule 15's point is that the wrong remedy costs more than none. + - *Start the sign-in again shortly.* What actually worked, twice. + + 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 ExportSourceError( + 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" + "Wait a minute or two and sign in again from the start. The code you entered has been" + " used up, so a new one will be sent. Apple may also refuse the password once while it" + " settles - that is part of the same hiccup, 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): diff --git a/python/test/test_retries.py b/python/test/test_retries.py index 8cc1b67a..1780637d 100644 --- a/python/test/test_retries.py +++ b/python/test/test_retries.py @@ -26,9 +26,11 @@ import pytest from findmy import InvalidCredentialsError, LoginState +from findmy.errors import UnhandledProtocolError from findmy.keychain.recovery import RecoveryError from exporter import icloud +from exporter.icloud import ExportSourceError RECORD = object() @@ -241,6 +243,129 @@ async def submit(self, code: str): return LoginState.LOGGED_IN +class FakeFactorThatTakesTheCodeThenFails: + """ + A second factor that models issue #168: the code is accepted, and signing in fails anyway. + + `td_2fa_submit` submits the code and *then* re-authenticates against Grand Slam. The second + half returned 503 and the first had already spent the code, which is why `submitted` records + the attempt even though nothing succeeded. + """ + + def __init__(self) -> None: + self.submitted: list[str] = [] + self.requests = 0 + + async def request(self) -> None: + self.requests += 1 + + async def submit(self, code: str): + self.submitted.append(code) + raise UnhandledProtocolError("Error response for GSA request: 503") + + +class TestACodeAppleTookAndThenFailedOn: + """ + Issue #168: Apple accepted the code, then answered 503 to the re-authentication behind it. + + **The recovery is to stop, and that is a finding rather than a shrug.** The one report that + recovered did so by starting the sign-in again - and the attempt in between was refused at the + *password* step, which looks like Apple throttling for a while. Sending two more codes into + that is how a throttle becomes a lock, so nothing here retries. + + What was wrong was never the retrying anyway. This escaped the loop entirely, landed in the + wizard's catch-all handler, and asked the one person who could do nothing about it to file a + bug. One duly did. + """ + + def test_it_is_recognised_as_a_spent_code(self): + assert icloud.code_was_already_spent( + UnhandledProtocolError("Error response for GSA request: 503")) + + def test_a_rejected_code_is_not_a_spent_one(self): + """The opposite case, and the one where re-typing is right.""" + assert not icloud.code_was_already_spent( + InvalidCredentialsError("Apple rejected that code.")) + + def test_it_stops_rather_than_asking_for_another_code(self): + """ + The decision this turns on. + + Retrying is untested against Apple and can only be tested on somebody's real account, so + it is not done - and `retry_code` must not even be consulted, because consulting it is how + an untested recovery gets offered by a later edit. + """ + factor = FakeFactorThatTakesTheCodeThenFails() + + with pytest.raises(ExportSourceError): + asyncio.run(icloud._submit_code_with_retries( + factor, lambda: _next(iter(["123456"])), _unused, + )) + + assert factor.requests == 0, "a throttled account must not be sent more codes" + assert factor.submitted == ["123456"], "exactly one attempt" + + def test_what_escapes_is_not_the_kind_that_asks_for_a_bug_report(self): + """ + The complaint, in one assertion. + + Both front ends show an ExportSourceError as a plain message and an unrecognised exception + with the issue link. Raising the protocol error unchanged is what put a person in front of + that link for weather. + """ + factor = FakeFactorThatTakesTheCodeThenFails() + + with pytest.raises(ExportSourceError) as raised: + asyncio.run(icloud._submit_code_with_retries( + factor, lambda: _next(iter(["123456"])), _unused, + )) + + assert not isinstance(raised.value, UnhandledProtocolError) + + def test_it_says_the_fault_is_apples_and_what_to_do(self): + """Not merely that it failed: a person reading this needs to know it is worth retrying.""" + factor = FakeFactorThatTakesTheCodeThenFails() + + with pytest.raises(ExportSourceError) as raised: + asyncio.run(icloud._submit_code_with_retries( + factor, lambda: _next(iter(["123456"])), _unused, + )) + + message = str(raised.value) + assert "Apple" in message + assert "sign in again" in message + assert "used up" in message, "they will wonder whether to keep the code they have" + + def test_the_status_code_survives_into_the_message_and_the_cause(self): + """ + 503 is the whole diagnosis if this ever turns out to be more than weather. + + Both, because the message is what reaches a bug report and `__cause__` is what reaches the + log with a traceback under it. + """ + factor = FakeFactorThatTakesTheCodeThenFails() + + with pytest.raises(ExportSourceError) as raised: + asyncio.run(icloud._submit_code_with_retries( + factor, lambda: _next(iter(["123456"])), _unused, + )) + + assert "503" in str(raised.value) + assert isinstance(raised.value.__cause__, UnhandledProtocolError) + + def test_a_rejected_code_still_reaches_the_retry_offer(self): + """The path this must not have broken.""" + factor = FakeFactor(accepts="123456") + codes = iter(["000000", "123456"]) + + async def retry(_error, _attempt): + return icloud.CODE_AGAIN + + assert asyncio.run(icloud._submit_code_with_retries( + factor, lambda: _next(codes), retry, + )) == LoginState.LOGGED_IN + + class TestAWrongPasswordCanBeCorrected: def test_a_typo_does_not_end_the_run(self): account = FakeAccount(state=LoginState.LOGGED_IN) From 612edf433e711425d183c3daabdaa950bb29aef5 Mon Sep 17 00:00:00 2001 From: "Shane B." Date: Sun, 30 Aug 2026 21:54:57 +0200 Subject: [PATCH 2/2] Wait Apple's fault out and send a new code, rather than giving up Issue #168. Apple accepted a verification code and answered 503 to the re-authentication behind it. The sign-in died in the wizard's catch-all handler - the one that names an exception type and links the issue tracker - so the one person who could do nothing about it was invited to file it, and one duly did. td_2fa_submit submits the code and *then* runs a full GSA re-authentication. The reported log shows the first half succeeding - "Attempting authentication for user" appears twice and only _gsa_authenticate logs that - and the second failing half a second later. Reproduced since. **Nothing the user can type helps.** The code is spent on the half that worked, so re-typing it is a guaranteed second failure, and there is no question worth putting to somebody with no way to judge the answer. The only recovery anyone has observed is time passing. So it waits, asks Apple for a new code itself, and prompts for that. The durations are the finding rather than a round number. The one recovery went: 503; then a whole manual round of re-typing the Apple ID and password, 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 failure the account was still being refused, and what eventually worked was about two rounds out. Hence 60s and then 120s, and a test that fails if either is quietly lowered. 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. The new code is requested *after* each wait, not before: Apple's codes expire, and one fetched first would be two minutes stale by the time it is typed. **And the waiting is visible, which needed a small thing in asyncui.** A progress window that says "Signing in to iCloud..." for three minutes is indistinguishable from a hung one, and this is a deliberate wait rather than a slow call. Asker.say now rewrites that line from the worker thread, so it counts down; the CLI rewrites one line on stderr. Without that, the fix would read as the bug it replaced. When both waits are spent it stops with a message saying so - as an ExportSourceError, which both front ends already show plainly with no invitation to report a bug, which was the entire complaint. It also warns that the next password attempt may be refused once, because that happened and otherwise reads as a second, unrelated fault. `from e` keeps 503 in the message and in __cause__. The wizard titles it "Could not finish signing in" rather than the generic "Could not read your accessories": nothing was read, and a dialog that misdescribes what happened is worse than a vague one. Nineteen tests across three files, all verified failable: giving up immediately turns three red, requesting the code before the wait turns one, and lowering the first wait to 20s turns one. Not fixed here: the Android app reaches the same library and sends the same 503 to its "this one is a bug" page. Same finding, its own change. Co-Authored-By: Claude Opus 5 --- python/exporter/asyncui.py | 58 +++++- python/exporter/cli.py | 21 +++ python/exporter/icloud.py | 113 ++++++++++-- python/exporter/wizard.py | 11 ++ python/test/test_retries.py | 173 ++++++++++++------ .../test/test_sign_in_interrupted_dialog.py | 140 ++++++++++++++ 6 files changed, 433 insertions(+), 83 deletions(-) create mode 100644 python/test/test_sign_in_interrupted_dialog.py diff --git a/python/exporter/asyncui.py b/python/exporter/asyncui.py index dab04c87..4f43f46b 100644 --- a/python/exporter/asyncui.py +++ b/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 diff --git a/python/exporter/cli.py b/python/exporter/cli.py index 6cb21399..113f30a1 100644 --- a/python/exporter/cli.py +++ b/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 diff --git a/python/exporter/icloud.py b/python/exporter/icloud.py index 495e7678..b232d69d 100644 --- a/python/exporter/icloud.py +++ b/python/exporter/icloud.py @@ -17,6 +17,7 @@ from __future__ import annotations +import asyncio import base64 import logging import uuid @@ -342,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" @@ -366,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. @@ -381,7 +402,11 @@ async def log_in( 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 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. + 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. """ @@ -396,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.") @@ -430,6 +455,18 @@ async def _log_in_with_retries(account, email, password, retry_credentials): raise AssertionError("unreachable") # pragma: no cover +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. @@ -450,7 +487,7 @@ def code_was_already_spent(error: BaseException) -> bool: return isinstance(error, UnhandledProtocolError) -async def _submit_code_with_retries(chosen, get_code, retry_code): +async def _submit_code_with_retries(chosen, get_code, retry_code, announce=None): """ Submit the verification code, letting a mistyped one be corrected. @@ -459,16 +496,26 @@ async def _submit_code_with_retries(chosen, get_code, retry_code): (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 stops instead of retrying**, and that is deliberate - rather than lazy - see :func:`code_was_already_spent` for what it is, and the message below for - why nothing is offered. + **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) - raise _apple_failed_after_taking_the_code(e) from 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) @@ -487,7 +534,35 @@ async def _submit_code_with_retries(chosen, get_code, retry_code): raise AssertionError("unreachable") # pragma: no cover -def _apple_failed_after_taking_the_code(error: BaseException) -> ExportSourceError: +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. @@ -495,25 +570,27 @@ def _apple_failed_after_taking_the_code(error: BaseException) -> ExportSourceErr 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 and carry on.* **Untested.** Nobody has observed this recovering, and the - one report that recovered did not do it. Worse, the sign-in that followed #168's 503 was - refused at the *password* step, which looks like Apple throttling the account or the machine - identity for a while - and requesting two more codes into that is how a throttle becomes a - lock. Rule 15's point is that the wrong remedy costs more than none. - - *Start the sign-in again shortly.* What actually worked, twice. + - *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 ExportSourceError( + 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" - "Wait a minute or two and sign in again from the start. The code you entered has been" - " used up, so a new one will be sent. Apple may also refuse the password once while it" - " settles - that is part of the same hiccup, and trying once more is the answer.", + 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.", ) diff --git a/python/exporter/wizard.py b/python/exporter/wizard.py index 2d3221fc..7341a373 100644 --- a/python/exporter/wizard.py +++ b/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), ), diff --git a/python/test/test_retries.py b/python/test/test_retries.py index 1780637d..f32447a4 100644 --- a/python/test/test_retries.py +++ b/python/test/test_retries.py @@ -249,33 +249,52 @@ class FakeFactorThatTakesTheCodeThenFails: `td_2fa_submit` submits the code and *then* re-authenticates against Grand Slam. The second half returned 503 and the first had already spent the code, which is why `submitted` records - the attempt even though nothing succeeded. + every attempt even when nothing succeeded. """ - def __init__(self) -> None: + def __init__(self, *, fail_first: int = 1) -> None: + self.fail_first = fail_first self.submitted: list[str] = [] self.requests = 0 + self.on_request = None async def request(self) -> None: self.requests += 1 + if self.on_request is not None: + self.on_request() async def submit(self, code: str): self.submitted.append(code) - raise UnhandledProtocolError("Error response for GSA request: 503") + + if len(self.submitted) <= self.fail_first: + raise UnhandledProtocolError("Error response for GSA request: 503") + + return LoginState.LOGGED_IN + + +@pytest.fixture +def no_waiting(monkeypatch): + """ + The same number of retries, with the waiting taken out. + + Patched rather than shortened in the source: the durations are the finding (see + `SPENT_CODE_WAITS`), and a suite that quietly ran with different ones would be testing + something nobody ships. + """ + monkeypatch.setattr(icloud, "SPENT_CODE_WAITS", tuple(0 for _ in icloud.SPENT_CODE_WAITS)) class TestACodeAppleTookAndThenFailedOn: """ Issue #168: Apple accepted the code, then answered 503 to the re-authentication behind it. - **The recovery is to stop, and that is a finding rather than a shrug.** The one report that - recovered did so by starting the sign-in again - and the attempt in between was refused at the - *password* step, which looks like Apple throttling for a while. Sending two more codes into - that is how a throttle becomes a lock, so nothing here retries. + Nothing the user could type recovers this - the code is spent - and the only recovery anyone + has observed is the passage of time. So it waits and asks for a new code itself, twice, and + only then says it could not. - What was wrong was never the retrying anyway. This escaped the loop entirely, landed in the - wizard's catch-all handler, and asked the one person who could do nothing about it to file a - bug. One duly did. + What was broken was never the retrying. This escaped the loop entirely, landed in the wizard's + catch-all handler, and asked the one person who could do nothing about it to file a bug. One + duly did. """ def test_it_is_recognised_as_a_spent_code(self): @@ -287,83 +306,117 @@ def test_a_rejected_code_is_not_a_spent_one(self): assert not icloud.code_was_already_spent( InvalidCredentialsError("Apple rejected that code.")) - def test_it_stops_rather_than_asking_for_another_code(self): + def test_it_waits_and_sends_a_new_code(self, no_waiting): + """The recovery, and that the code is a *new* one rather than the spent one re-typed.""" + factor = FakeFactorThatTakesTheCodeThenFails(fail_first=1) + codes = iter(["111111", "222222"]) + + state = asyncio.run(icloud._submit_code_with_retries( + factor, lambda: _next(codes), _unused, + )) + + assert state == LoginState.LOGGED_IN + assert factor.requests == 1, "a spent code has to be replaced" + assert factor.submitted == ["111111", "222222"] + + def test_the_user_is_never_asked_about_it(self, no_waiting): """ - The decision this turns on. + `retry_code` must not be consulted, and that is load-bearing. - Retrying is untested against Apple and can only be tested on somebody's real account, so - it is not done - and `retry_code` must not even be consulted, because consulting it is how - an untested recovery gets offered by a later edit. + There is no question worth asking: re-typing cannot work and waiting is the only option, + so a prompt would be asking somebody to choose between one real answer and a wrong one. + Asserted because a retry path that never fires looks harmless in review. """ - factor = FakeFactorThatTakesTheCodeThenFails() + factor = FakeFactorThatTakesTheCodeThenFails(fail_first=1) + codes = iter(["111111", "222222"]) + + asyncio.run(icloud._submit_code_with_retries(factor, lambda: _next(codes), _unused)) + + def test_it_gives_up_after_the_waits_run_out(self, no_waiting): + """A fault that does not clear must stop, rather than sending codes forever.""" + factor = FakeFactorThatTakesTheCodeThenFails(fail_first=99) + codes = iter([str(n) * 6 for n in range(icloud.MAX_CODE_ATTEMPTS)]) with pytest.raises(ExportSourceError): - asyncio.run(icloud._submit_code_with_retries( - factor, lambda: _next(iter(["123456"])), _unused, - )) + asyncio.run(icloud._submit_code_with_retries(factor, lambda: _next(codes), _unused)) - assert factor.requests == 0, "a throttled account must not be sent more codes" - assert factor.submitted == ["123456"], "exactly one attempt" + assert factor.requests == len(icloud.SPENT_CODE_WAITS) + assert len(factor.submitted) == icloud.MAX_CODE_ATTEMPTS - def test_what_escapes_is_not_the_kind_that_asks_for_a_bug_report(self): + def test_there_is_a_wait_for_every_retry(self): """ - The complaint, in one assertion. + The two constants are coupled by an index, and nothing else says so. - Both front ends show an ExportSourceError as a plain message and an unrecognised exception - with the issue link. Raising the protocol error unchanged is what put a person in front of - that link for weather. + `SPENT_CODE_WAITS[attempt - 1]` is read on every attempt but the last, so raising the + attempt cap without adding a duration is an IndexError in front of a user mid-sign-in. """ - factor = FakeFactorThatTakesTheCodeThenFails() + assert len(icloud.SPENT_CODE_WAITS) == icloud.MAX_CODE_ATTEMPTS - 1 - with pytest.raises(ExportSourceError) as raised: - asyncio.run(icloud._submit_code_with_retries( - factor, lambda: _next(iter(["123456"])), _unused, - )) + def test_the_waits_clear_the_interval_that_was_seen_to_fail(self): + """ + The floor the one observed recovery puts under this. - assert not isinstance(raised.value, UnhandledProtocolError) + A whole manual round - re-typing the Apple ID and password, waiting for a code, entering + it - is the better part of a minute, and the attempt *after* that round was still refused. + So a first wait materially under a minute is known to be too short, and this is the number + that would have to be argued with rather than quietly lowered. + """ + assert icloud.SPENT_CODE_WAITS[0] >= 60 + assert sum(icloud.SPENT_CODE_WAITS) >= 180, "the recovery seen was about two rounds out" - def test_it_says_the_fault_is_apples_and_what_to_do(self): - """Not merely that it failed: a person reading this needs to know it is worth retrying.""" - factor = FakeFactorThatTakesTheCodeThenFails() + def test_the_new_code_is_requested_after_the_wait_not_before(self, no_waiting): + """ + Apple's codes expire, so one fetched before a two-minute wait is two minutes stale by the + time it is typed. Ordering asserted because both orders look correct in a diff. + """ + factor = FakeFactorThatTakesTheCodeThenFails(fail_first=1) + order: list[str] = [] - with pytest.raises(ExportSourceError) as raised: - asyncio.run(icloud._submit_code_with_retries( - factor, lambda: _next(iter(["123456"])), _unused, - )) + async def announce_free(_text: str) -> None: # pragma: no cover - not awaited + pass - message = str(raised.value) - assert "Apple" in message - assert "sign in again" in message - assert "used up" in message, "they will wonder whether to keep the code they have" + factor.on_request = lambda: order.append("requested") + asyncio.run(icloud._wait_then_send_a_new_code( + factor, 2, lambda text: order.append(text))) + + assert order[-1] == "requested", "the code must be the last thing fetched" + assert any("2s" in step for step in order[:-1]), "it counts down before asking" - def test_the_status_code_survives_into_the_message_and_the_cause(self): + def test_what_escapes_is_not_the_kind_that_asks_for_a_bug_report(self, no_waiting): """ - 503 is the whole diagnosis if this ever turns out to be more than weather. + The complaint, in one assertion. - Both, because the message is what reaches a bug report and `__cause__` is what reaches the - log with a traceback under it. + Both front ends show an ExportSourceError as a plain message and an unrecognised exception + with the issue link. Raising the protocol error unchanged is what put a person in front of + that link for weather. """ - factor = FakeFactorThatTakesTheCodeThenFails() + factor = FakeFactorThatTakesTheCodeThenFails(fail_first=99) + codes = iter([str(n) * 6 for n in range(icloud.MAX_CODE_ATTEMPTS)]) with pytest.raises(ExportSourceError) as raised: - asyncio.run(icloud._submit_code_with_retries( - factor, lambda: _next(iter(["123456"])), _unused, - )) + asyncio.run(icloud._submit_code_with_retries(factor, lambda: _next(codes), _unused)) + assert not isinstance(raised.value, UnhandledProtocolError) assert "503" in str(raised.value) assert isinstance(raised.value.__cause__, UnhandledProtocolError) - def test_a_rejected_code_still_reaches_the_retry_offer(self): - """The path this must not have broken.""" - factor = FakeFactor(accepts="123456") - codes = iter(["000000", "123456"]) + def test_it_says_it_already_waited(self, no_waiting): + """ + Otherwise the advice reads as "just try again", which is what they have been doing. - async def retry(_error, _attempt): - return icloud.CODE_AGAIN + Somebody who has watched it wait three minutes needs to be told that is what happened, or + the message is asking them to repeat work the program already did. + """ + factor = FakeFactorThatTakesTheCodeThenFails(fail_first=99) + codes = iter([str(n) * 6 for n in range(icloud.MAX_CODE_ATTEMPTS)]) - assert asyncio.run(icloud._submit_code_with_retries( - factor, lambda: _next(codes), retry, - )) == LoginState.LOGGED_IN + with pytest.raises(ExportSourceError) as raised: + asyncio.run(icloud._submit_code_with_retries(factor, lambda: _next(codes), _unused)) + + message = str(raised.value) + assert "chances to settle" in message + assert "Apple's side" in message + assert "password" in message, "the next attempt may be refused once, and that surprised us" class TestAWrongPasswordCanBeCorrected: diff --git a/python/test/test_sign_in_interrupted_dialog.py b/python/test/test_sign_in_interrupted_dialog.py new file mode 100644 index 00000000..3280f096 --- /dev/null +++ b/python/test/test_sign_in_interrupted_dialog.py @@ -0,0 +1,140 @@ +""" +What the wizard says when Apple takes a verification code and then fails anyway. + +**Issue #168, and specifically the heading over it.** The failure itself is Apple's - a 503 from +Grand Slam half a second after the code was accepted - and the exporter's part was showing the +wrong thing about it. Twice, as it turned out: + +- it fell through to the catch-all handler, which names an exception type and asks for a bug + report, so the one person who could do nothing about it was invited to file it +- and once that was fixed, the generic message dialog titled it "Could not read your accessories", + which is not what happened. Nothing was read; signing in never finished. + +A dialog that misdescribes what happened is worse than a vague one, because the reader corrects +for it and then trusts the rest of it less - so the title is asserted, not just the body. +""" + +from __future__ import annotations + +from unittest import mock + +import pytest + +# Before anything that imports tkinter - a skip inside a fixture is too late, because the module +# is imported during collection. +tk = pytest.importorskip("tkinter", reason="needs a Python built with Tk") + +from findmy.errors import UnhandledProtocolError # noqa: E402 + +from exporter import icloud, wizard # noqa: E402 +from exporter.icloud import ExportSourceError # noqa: E402 + + +@pytest.fixture(scope="module") +def window(): + """ + One window for the whole module. + + Built once rather than per test: repeatedly creating and destroying a `Tk` in one process is + unstable on macOS. Nothing here mutates window state. + """ + try: + app = wizard.WizardApp() + except tk.TclError as e: # pragma: no cover - depends on the machine, not on the code + pytest.skip(f"needs a display to build a window: {e}") + + app.withdraw() + try: + yield app + finally: + app.destroy() + + +def load_failing_with(window, error): + """Press Read, with the sign-in raising this, and return what was shown.""" + with mock.patch.object(wizard, "run_with_progress", side_effect=error), \ + mock.patch.object(wizard.messagebox, "showerror") as shown: + window._load() + + assert shown.called, "the failure was swallowed" + return shown.call_args.args + + +THE_REAL_ONE = icloud._apple_failed_after_taking_the_code( + UnhandledProtocolError("Error response for GSA request: 503")) + + +class TestTheHeadingSaysWhatFailed: + def test_it_says_signing_in_rather_than_reading_accessories(self, window): + title, _body = load_failing_with(window, THE_REAL_ONE) + + assert "signing in" in title.lower() + assert "accessories" not in title.lower(), ( + "nothing was read - signing in never finished") + + def test_everything_else_keeps_the_heading_it_had(self, window): + """ + The handler above must not have widened. + + It is placed before the general one and catches a subclass, so a mistake here is easy to + make and invisible: every source failure would quietly start claiming to be a sign-in. + """ + title, _body = load_failing_with( + window, ExportSourceError("The bundle could not be read.")) + + assert title == "Could not read your accessories" + + +class TestTheBodySaysWhoseFaultItIsAndWhatToDo: + def test_it_does_not_ask_for_a_bug_report(self, window): + """ + The complaint, asserted. + + This is what the catch-all handler adds, and reaching it is what produced issue #168. + """ + _title, body = load_failing_with(window, THE_REAL_ONE) + + assert "report" not in body.lower() + assert "github.com" not in body.lower() + + def test_it_says_the_fault_is_apples(self, window): + _title, body = load_failing_with(window, THE_REAL_ONE) + + assert "Apple's side" in body + assert "rather than anything you did" in body + + def test_it_says_it_already_waited(self, window): + """ + Otherwise the advice reads as "just try again", which is what they have been doing. + + Somebody who has watched the progress window count down for three minutes needs to be told + that is what it was doing, or this is asking them to repeat work the program already did. + """ + _title, body = load_failing_with(window, THE_REAL_ONE) + + assert "chances to settle" in body + assert str(icloud.SPENT_CODE_WAITS[0]) in body + + def test_it_warns_the_password_may_be_refused_once(self, window): + """ + Because it was, and it read as a second unrelated fault. + + The reproduction went: 503 after the code, then a *password* rejection on the next + attempt, then success. Somebody not told to expect the middle one concludes they have + mistyped a password they have typed correctly for years. + """ + _title, body = load_failing_with(window, THE_REAL_ONE) + + assert "password" in body + + def test_it_keeps_the_status_code(self, window): + """503 is the whole diagnosis if this ever turns out to be more than weather.""" + _title, body = load_failing_with(window, THE_REAL_ONE) + + assert "503" in body + + def test_it_says_nothing_was_sent(self, window): + """The first question anybody asks after a failed sign-in to their own Apple account.""" + _title, body = load_failing_with(window, THE_REAL_ONE) + + assert "nothing was sent" in body.lower()