Logging and possible fix for unsubmitted login form

ocma/connect.py

@@ -1,3 +1,4 @@
+import logging
 import time
 from dataclasses import dataclass
 from typing import Optional
@@ -26,6 +27,18 @@ MFA_MAX_RETRY_COUNT = 3
 ELEMENT_CHECK_DELAY = 0.5
 DOMAIN_CHECK_DELAY = 0.5
 
+LOGGER = logging.getLogger("OCMA")
+LOGGER.setLevel(logging.INFO)
+
+fh = logging.FileHandler("ocma.log")
+fh.setLevel(logging.DEBUG)
+
+fh_s = logging.StreamHandler()
+fh_s.setLevel(logging.DEBUG)
+
+LOGGER.addHandler(fh)
+LOGGER.addHandler(fh_s)
+
 
 @dataclass
 class VPNCookie:
@@ -40,9 +53,11 @@ def login(
     vpn_site: str = "https://vpn.fhnw.ch",
     headless: bool = True,
 ) -> VPNCookie:
-    options = FirefoxOptions()
+    LOGGER.info("Starting")
 
+    options = FirefoxOptions()
     if headless:
+        LOGGER.info("Running in headless mode")
         options.add_argument("--headless")
 
     driver = webdriver.Firefox(options=options)
@@ -54,7 +69,9 @@ def login(
         time.sleep(DOMAIN_CHECK_DELAY)
 
     if retries < 0:
-        raise ValueError("We never reached the MS login page!")
+        raise ValueError(
+            f"We never reached the MS login page! Currently on {driver.current_url}"
+        )
 
     _fill_login(driver, username, password)
     _fill_mfa(driver, mfa_secret)
@@ -64,6 +81,8 @@ def login(
 
 
 def _fill_login(driver: webdriver.Firefox, username: str, password: str) -> None:
+    LOGGER.info("Filling in login information")
+
     _check_on_ms_login_page(driver)
 
     if not _find_element(driver, By.NAME, USERNAME_INPUT_NAME):
@@ -74,8 +93,29 @@ def _fill_login(driver: webdriver.Firefox, username: str, password: str) -> None
     click_continue(driver)  # Confirm username
     click_continue(driver)  # Confirm password
 
+    on_login_form = lambda: "saml2" in driver.current_url
+
+    retries = MAX_RETRY_DOMAIN_CHECK
+    while on_login_form() and retries > 0:
+        LOGGER.info(
+            f"Login information may not have yet been confirmed. Checking again (Try {MAX_RETRY_DOMAIN_CHECK - retries + 1} of {MAX_RETRY_DOMAIN_CHECK})"
+        )
+        time.sleep(ELEMENT_CHECK_DELAY)
+
+        if on_login_form():
+            LOGGER.info("Login information has not yet been confirmed. Trying again")
+            click_continue(driver)  # Confirm password
+        retries -= 1
+
+    if retries < 0:
+        raise ValueError("Failed to confirm login form!")
+
+    LOGGER.info("Login information filled out")
+
 
 def _fill_mfa(driver: webdriver.Firefox, mfa_secret: Optional[str]) -> None:
+    LOGGER.info("Checking if we can fill in MFA information")
+
     _check_on_ms_login_page(driver)
 
     # Check if we have the MFA page
@@ -84,9 +124,13 @@ def _fill_mfa(driver: webdriver.Firefox, mfa_secret: Optional[str]) -> None:
 
     # Check if we have an MFA code to enter
     if mfa_secret is None:
+        LOGGER.info("Filling in login information")
         return
 
-    for _ in range(MFA_MAX_RETRY_COUNT):
+    for i in range(MFA_MAX_RETRY_COUNT):
+        LOGGER.info(
+            f"Filling in MFA information (Try {i + 1} of {MFA_MAX_RETRY_COUNT})"
+        )
         if not _find_element(driver, By.NAME, MFA_INPUT_NAME):
             time.sleep(ELEMENT_CHECK_DELAY)
             continue
@@ -95,24 +139,35 @@ def _fill_mfa(driver: webdriver.Firefox, mfa_secret: Optional[str]) -> None:
         driver.find_element(By.NAME, MFA_INPUT_NAME).send_keys(mfa_code)
         click_continue(driver, MFA_CONTINUE_BUTTON_ID)  # Confirm otp
 
+        LOGGER.info(f"Confirmed MFA code")
+
         if not driver.current_url.endswith("/login"):
             # We have moved on
+            LOGGER.info(f"We have moved away from the MFA page")
             break
 
         # Check for any errors
         if not _find_element(driver, By.ID, MFA_ERROR_TEXT_ID, 2):
             # Did not find an error
+            LOGGER.info(f"MFA seems to have been accepted, no errors")
             break
 
 
 def _confirm_stay_signed_in(driver: webdriver.Firefox) -> bool:
+    LOGGER.info(f"Cheking if we should confirm if we should stay signed in")
+
     if not _is_on_ms_login_page(driver):
+        LOGGER.info(f"Already logged in, can't confirm 'stay signed in'")
         return False
 
     if not driver.current_url.endswith("/common/SAS/ProcessAuth"):
+        LOGGER.info(
+            f"We have reached a dead end. We have completed the login, but not on the 'stay signed in' page"
+        )
         return False
 
     click_continue(driver)  # Confirm stay signed in
+    LOGGER.info(f"Confirmed to 'stay signed in'")
     return True