Add more logging to provisioning API login

mauigpapi/http/challenge.py

@@ -30,6 +30,7 @@ class ChallengeAPI(BaseAndroidAPI):
             "guid": self.state.device.uuid,
             "device_id": self.state.device.id,
         }
+        self.log.debug("Fetching current challenge state")
         return self.__handle_resp(
             await self.std_http_get(self.__path, query=query, response_type=ChallengeStateResponse)
         )
@@ -46,6 +47,7 @@ class ChallengeAPI(BaseAndroidAPI):
             "guid": self.state.device.uuid,
             "device_id": self.state.device.id,
         }
+        self.log.debug(f"Selecting challenge method {choice} (replay: {is_replay})")
         return self.__handle_resp(
             await self.std_http_post(path, data=req, response_type=ChallengeStateResponse)
         )
@@ -60,6 +62,7 @@ class ChallengeAPI(BaseAndroidAPI):
             "guid": self.state.device.uuid,
             "device_id": self.state.device.id,
         }
+        self.log.debug("Sending challenge phone number")
         return self.__handle_resp(
             await self.std_http_post(self.__path, data=req, response_type=ChallengeStateResponse)
         )
@@ -72,6 +75,7 @@ class ChallengeAPI(BaseAndroidAPI):
             "device_id": self.state.device.id,
         }
         try:
+            self.log.debug("Sending challenge security code")
             return self.__handle_resp(
                 await self.std_http_post(
                     self.__path, data=req, response_type=ChallengeStateResponse
@@ -88,6 +92,7 @@ class ChallengeAPI(BaseAndroidAPI):
             "guid": self.state.device.uuid,
             "device_id": self.state.device.id,
         }
+        self.log.debug("Resetting challenge")
         return self.__handle_resp(
             await self.std_http_post(
                 self.__path.replace("/challenge/", "/challenge/reset/"),
@@ -101,13 +106,23 @@ class ChallengeAPI(BaseAndroidAPI):
             await self.challenge_reset()
         challenge = self.state.challenge or await self.challenge_get_state()
         if challenge.step_name == "select_verify_method":
+            self.log.debug(
+                "Got select_verify_method challenge step, "
+                f"auto-selecting {challenge.step_data.choice}"
+            )
             return await self.challenge_select_method(challenge.step_data.choice)
         elif challenge.step_name == "delta_login_review":
+            self.log.debug("Got delta_login_review challenge step, auto-selecting was_me=True")
             return await self.challenge_delta_review(was_me=True)
+        else:
+            self.log.debug(f"Got unknown challenge step {challenge.step_name}, not doing anything")
         return challenge
 
     def __handle_resp(self, resp: ChallengeStateResponse) -> ChallengeStateResponse:
         if resp.action == "close":
+            self.log.debug(
+                f"Challenge closed (step: {resp.step_name}, has user: {bool(resp.logged_in_user)})"
+            )
             self.state.challenge = None
             self.state.challenge_path = None
         else:

mautrix_instagram/user.py

@@ -153,25 +153,27 @@ class User(DBUser, BaseUser):
     def is_connected(self) -> bool:
         return bool(self.client) and bool(self.mqtt) and self._is_connected
 
-    async def connect(self) -> None:
+    async def connect(self, user: CurrentUser | None = None) -> None:
         client = AndroidAPI(self.state, log=self.api_log)
 
-        try:
-            resp = await client.current_user()
-        except IGNotLoggedInError as e:
-            self.log.warning(f"Failed to connect to Instagram: {e}, logging out")
-            await self.send_bridge_notice(
-                f"You have been logged out of Instagram: {e!s}",
-                important=True,
-                error_code="ig-auth-error",
-                error_message=str(e),
-            )
-            await self.logout(from_error=True)
-            return
+        if not user:
+            try:
+                resp = await client.current_user()
+                user = resp.user
+            except IGNotLoggedInError as e:
+                self.log.warning(f"Failed to connect to Instagram: {e}, logging out")
+                await self.send_bridge_notice(
+                    f"You have been logged out of Instagram: {e!s}",
+                    important=True,
+                    error_code="ig-auth-error",
+                    error_message=str(e),
+                )
+                await self.logout(from_error=True)
+                return
         self.client = client
         self._is_logged_in = True
-        self.igpk = resp.user.pk
-        self.username = resp.user.username
+        self.igpk = user.pk
+        self.username = user.username
         await self.push_bridge_state(BridgeStateEvent.CONNECTING)
         self._track_metric(METRIC_LOGGED_IN, True)
         self.by_igpk[self.igpk] = self
@@ -187,7 +189,7 @@ class User(DBUser, BaseUser):
 
         await self.update()
 
-        self.loop.create_task(self._try_sync_puppet(resp.user))
+        self.loop.create_task(self._try_sync_puppet(user))
         self.loop.create_task(self._try_sync())
 
     async def on_connect(self, evt: Connect) -> None:

mautrix_instagram/web/provisioning_api.py

@@ -31,7 +31,7 @@ from mauigpapi.errors import (
     IGLoginTwoFactorRequiredError,
     IGNotLoggedInError,
 )
-from mauigpapi.types import BaseResponseUser
+from mauigpapi.types import ChallengeStateResponse, LoginResponse, LoginResponseUser
 from mautrix.types import JSON, UserID
 from mautrix.util.logging import TraceLogger
 
@@ -160,25 +160,7 @@ class ProvisioningAPI:
             )
         except IGCheckpointError as e:
             self.log.debug("%s logged in as %s, but got a checkpoint", user.mxid, username)
-            try:
-                await api.challenge_auto(reset=True)
-            except Exception as e:
-                # Most likely means that the user has to go and verify the login on their phone.
-                # Return a 403 in this case so the client knows to show such verbiage.
-                self.log.exception("Challenge reset failed")
-                return web.json_response(
-                    data={"status": "checkpoint", "response": e},
-                    status=403,
-                    headers=self._acao_headers,
-                )
-            return web.json_response(
-                data={
-                    "status": "checkpoint",
-                    "response": e.body.serialize(),
-                },
-                status=202,
-                headers=self._acao_headers,
-            )
+            return await self.start_checkpoint(user, api, e)
         except IGLoginInvalidUserError:
             self.log.debug("%s tried to log in as non-existent user %s", user.mxid, username)
             return web.json_response(
@@ -193,8 +175,7 @@ class ProvisioningAPI:
                 status=403,
                 headers=self._acao_headers,
             )
-        self.log.debug("%s finished login after password, trying to connect", user.mxid)
-        return await self._finish_login(user, state, resp.logged_in_user)
+        return await self._finish_login(user, state, api, login_resp=resp, after="password")
 
     async def _get_user(
         self, request: web.Request, check_state: bool = False
@@ -240,27 +221,39 @@ class ProvisioningAPI:
             )
         except IGCheckpointError as e:
             self.log.debug("%s submitted a 2-factor auth code, but got a checkpoint", user.mxid)
-            try:
-                await api.challenge_auto(reset=True)
-            except Exception as e:
-                # Most likely means that the user has to go and verify the login on their phone.
-                # Return a 403 in this case so the client knows to show such verbiage.
-                self.log.exception("Challenge reset failed")
-                return web.json_response(
-                    data={"status": "checkpoint", "response": e},
-                    status=403,
-                    headers=self._acao_headers,
-                )
+            return await self.start_checkpoint(user, api, e)
+        return await self._finish_login(user, state, api, login_resp=resp, after="2-factor auth")
+
+    async def start_checkpoint(
+        self, user: u.User, api: AndroidAPI, err: IGCheckpointError
+    ) -> web.Response:
+        try:
+            resp = await api.challenge_auto(reset=True)
+        except Exception as e:
+            # Most likely means that the user has to go and verify the login on their phone.
+            # Return a 403 in this case so the client knows to show such verbiage.
+            self.log.exception("Challenge reset failed for %s", user.mxid)
             return web.json_response(
-                data={
-                    "status": "checkpoint",
-                    "response": e.body.serialize(),
-                },
-                status=202,
+                data={"status": "checkpoint", "response": e},
+                status=403,
                 headers=self._acao_headers,
             )
-        self.log.debug("%s finished login after 2-factor auth, trying to connect", user.mxid)
-        return await self._finish_login(user, state, resp.logged_in_user)
+        challenge_data = resp.serialize()
+        liu: LoginResponseUser = challenge_data.pop("logged_in_user", None)
+        self.log.debug(
+            "Challenge state for %s after auto handling: %s (logged in user: %s)",
+            user.mxid,
+            challenge_data,
+            f"{liu.pk}/{liu.username}" if liu else "null",
+        )
+        return web.json_response(
+            data={
+                "status": "checkpoint",
+                "response": err.body.serialize(),
+            },
+            status=202,
+            headers=self._acao_headers,
+        )
 
     async def login_checkpoint(self, request: web.Request) -> web.Response:
         user, data = await self._get_user(request, check_state=True)
@@ -284,21 +277,55 @@ class ProvisioningAPI:
                 status=403,
                 headers=self._acao_headers,
             )
-        self.log.debug("%s finished login after checkpoint, trying to connect", user.mxid)
-        return await self._finish_login(user, state, resp.logged_in_user)
+        challenge_data = resp.serialize()
+        liu: LoginResponseUser = challenge_data.pop("logged_in_user", None)
+        self.log.debug(
+            "Challenge state for %s after sending security code: %s (logged in user: %s)",
+            user.mxid,
+            challenge_data,
+            f"{liu.pk}/{liu.username}" if liu else "null",
+        )
+        return await self._finish_login(user, state, api, login_resp=resp, after="checkpoint")
 
     async def _finish_login(
-        self, user: u.User, state: AndroidState, resp_user: BaseResponseUser
+        self,
+        user: u.User,
+        state: AndroidState,
+        api: AndroidAPI,
+        login_resp: LoginResponse | ChallengeStateResponse,
+        after: str,
     ) -> web.Response:
+        self.log.debug(
+            "%s finished login after %s, trying to connect "
+            "(login response status: %s, logged in user ID: %s)",
+            user.mxid,
+            after,
+            login_resp.status,
+            login_resp.logged_in_user.pk if login_resp.logged_in_user else None,
+        )
         user.state = state
         pl = state.device.payload
         manufacturer, model = pl["manufacturer"], pl["model"]
-        await user.try_connect()
+        try:
+            resp = await api.current_user()
+        except IGCheckpointError as e:
+            if isinstance(login_resp, ChallengeStateResponse):
+                self.log.debug(
+                    "%s got a checkpoint after a login that looked successful, "
+                    "failing login because we already did some checkpointing",
+                    user.mxid,
+                )
+                # TODO this should probably return a proper error
+                # and there might be some cases that can still be handled
+                raise
+            self.log.debug("%s got a checkpoint after a login that looked successful", user.mxid)
+            return await self.start_checkpoint(user, api, e)
+        await user.connect()
         return web.json_response(
             data={
                 "status": "logged-in",
                 "device_displayname": f"{manufacturer} {model}",
-                "user": resp_user.serialize() if resp_user else None,
+                "user": resp.user.serialize() if resp and resp.user else None,
             },
             status=200,
             headers=self._acao_headers,