Timeout reached when waiting for authentication

[lazerlabs]

Describe the bug
I'm trying to run latest docker image available but when I run it the authentication times out

2024-05-15 15:58:34,720|I| Submitting the form
2024-05-15 15:58:50,151|E| Timeout reached when waiting for authentication. The website seems to not be loaded correctly. Consider increasing IBEAM_PAGE_LOAD_TIMEOUT.
Website URL: https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on

Exception:
  File "/srv/ibeam/ibeam_starter.py", line 167, in <module>
    success, shutdown, status = client.start_and_authenticate()
  File "/srv/ibeam/src/gateway_client.py", line 53, in start_and_authenticate
    success, shutdown, status = self.strategy_handler.try_authenticating(request_retries=request_retries)
  File "/srv/ibeam/src/handlers/strategy_handler.py", line 85, in try_authenticating
    return self._authentication_strategy_B(status, request_retries)
  File "/srv/ibeam/src/handlers/strategy_handler.py", line 140, in _authentication_strategy_B
    return self._log_in(status)
  File "/srv/ibeam/src/handlers/strategy_handler.py", line 151, in _log_in
    success, shutdown = self.login_handler.login()
  File "/srv/ibeam/src/handlers/login_handler.py", line 454, in login
    self.handle_timeout_exception(e, targets, driver, website_version, self.route_auth, self.base_url, self.outputs_dir)
  File "/srv/ibeam/src/handlers/login_handler.py", line 435, in login
    self.attempt(targets, wait_and_identify_trigger, driver)
  File "/srv/ibeam/src/handlers/login_handler.py", line 359, in attempt
    trigger, target = self.step_login(targets, wait_and_identify_trigger, driver, self.secrets_handler.account, self.secrets_handler.password, self.secrets_handler.key, self.presubmit_buffer)
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/srv/ibeam/src/handlers/login_handler.py", line 180, in step_login
    trigger, target = wait_and_identify_trigger(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/srv/ibeam/src/handlers/login_handler.py", line 67, in _wait_and_identify_trigger
    trigger = WebDriverWait(driver, timeout).until(any_of(*expected_conditions))
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/support/wait.py", line 95, in until
    raise TimeoutException(message, screen, stacktrace)

  <class 'selenium.common.exceptions.TimeoutException'> Message:

See below for the full log.

To Reproduce
Steps to reproduce the behavior:

1. Run
   docker run --env IBEAM_PAGE_LOAD_TIMEOUT=300 --env IBEAM_TWO_FA_HANDLER=HTTP_CALLBACK --env IBEAM_REAUTHENTICATE_WAIT=300 --env IBEAM_ACCOUNT=username --env IBEAM_PASSWORD=password -it voyz/ibeam:0.5.3
2. See error

Environment
IBeam version: 0.5.3
Docker image or standalone: docker
OS: Linux ubuntuserver 5.15.0-106-generic #116-Ubuntu SMP Wed Apr 17 09:17:56 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 22.04.3 LTS
Release: 22.04
Codename: jammy

Additional context
I noticed this behaviour while implementing an http_callback TFA handler (see my fork: https://github.com/lazerlabs/ibeam/blob/master/ibeam/src/two_fa_handlers/http_callback.py) but it happens the same with voyz/ibeam:0.5.3

(I can provide more details about how this would work, and I would send a pull request, but I wanted to test it for a while and atm I can't for this issue)

Here's the full log:

❯ docker run --env IBEAM_PAGE_LOAD_TIMEOUT=300   --env IBEAM_TWO_FA_HANDLER=HTTP_CALLBACK  --env IBEAM_REAUTHENTICATE_WAIT=300 --env IBEAM_ACCOUNT=username --env IBEAM_PASSWORD=password -p 8088:8088 -it voyz/ibeam:0.5.3
2024-05-15 16:11:10,435|I| ############ Starting IBeam version 0.5.3 ############
2024-05-15 16:11:10,438|I| Secrets source: env
2024-05-15 16:11:10,439|I| Health server started at port=5001
2024-05-15 16:11:10,439|I| Configuration:
{'INPUTS_DIR': '/srv/inputs/', 'OUTPUTS_DIR': '/srv/outputs', 'GATEWAY_DIR': '/srv/clientportal.gw', 'CHROME_DRIVER_PATH': '/usr/bin/chromedriver', 'GATEWAY_STARTUP': 20, 'GATEWAY_PROCESS_MATCH': 'ibgroup.web.core.clientportal.gw.GatewayStart', 'MAINTENANCE_INTERVAL': 60, 'SPAWN_NEW_PROCESSES': False, 'LOG_LEVEL': 'INFO', 'LOG_TO_FILE': True, 'LOG_FORMAT': '%(asctime)s|%(levelname)-.1s| %(message)s', 'REQUEST_RETRIES': 2, 'REQUEST_TIMEOUT': 15, 'RESTART_FAILED_SESSIONS': True, 'RESTART_WAIT': 15, 'REAUTHENTICATE_WAIT': 300, 'HEALTH_SERVER_PORT': 5001, 'SECRETS_SOURCE': 'env', 'GCP_SECRETS_URL': None, 'GATEWAY_BASE_URL': 'https://localhost:5000', 'ROUTE_AUTH': '/sso/Login?forwardTo=22&RL=1&ip2loc=on', 'ROUTE_VALIDATE': '/v1/portal/sso/validate', 'ROUTE_REAUTHENTICATE': '/v1/portal/iserver/reauthenticate?force=true', 'ROUTE_INITIALISE': '/v1/api/iserver/auth/ssodh/init', 'ROUTE_AUTH_STATUS': '/v1/api/iserver/auth/status', 'ROUTE_TICKLE': '/v1/api/tickle', 'ROUTE_LOGOUT': '/v1/api/logout', 'USER_NAME_EL': None, 'PASSWORD_EL': 'NAME@@password', 'SUBMIT_EL': 'CSS_SELECTOR@@.btn.btn-lg.btn-primary', 'ERROR_EL': None, 'SUCCESS_EL_TEXT': 'TAG_NAME@@Client login succeeds', 'OAUTH_TIMEOUT': 15, 'PAGE_LOAD_TIMEOUT': 300, 'ERROR_SCREENSHOTS': False, 'MAX_FAILED_AUTH': 5, 'MIN_PRESUBMIT_BUFFER': 5, 'MAX_PRESUBMIT_BUFFER': 30, 'MAX_IMMEDIATE_ATTEMPTS': 10, 'IBKEY_PROMO_EL_CLASS': 'CLASS_NAME@@ibkey-promo-skip', 'AUTHENTICATION_STRATEGY': 'B', 'MAX_STATUS_CHECK_RETRIES': 120, 'MAX_REAUTHENTICATE_RETRIES': 3, 'UI_SCALING': 1.0, 'TWO_FA_EL_ID': 'ID@@twofactbase', 'TWO_FA_NOTIFICATION_EL': 'CLASS_NAME@@login-step-notification', 'TWO_FA_INPUT_EL_ID': 'ID@@chlginput', 'TWO_FA_HANDLER': 'HTTP_CALLBACK', 'STRICT_TWO_FA_CODE': True, 'TWO_FA_SELECT_EL_ID': 'ID@@sf_select', 'TWO_FA_SELECT_TARGET': 'IB Key', 'CUSTOM_TWO_FA_HANDLER': 'custom_two_fa_handler.CustomTwoFaHandler'}
2024-05-15 16:11:10,440|I| Gateway not found, starting new one...
2024-05-15 16:11:10,440|I| Note that the Gateway log below may display "Open https://localhost:[PORT] to login" - ignore this command.
2024-05-15 16:11:10,440|I| Starting Gateway as Linux process with params: ['bash', 'bin/run.sh', 'root/conf.yaml']
running
 runtime path : root:dist/ibgroup.web.core.iblink.router.clientportal.gw.jar:build/lib/runtime/*
 config file  : root/conf.yaml
2024-05-15 16:11:10,445|I| Gateway started with pids: [13]
2024-05-15 16:11:10,446|I| Cannot ping Gateway. Retrying for another 20 seconds
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by io.netty.util.internal.ReflectionUtil (file:/srv/clientportal.gw/build/lib/runtime/netty-common-4.1.15.Final.jar) to constructor java.nio.DirectByteBuffer(long,int)
WARNING: Please consider reporting this to the maintainers of io.netty.util.internal.ReflectionUtil
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
 -> mount demo on /demo
Java Version: 11.0.20
****************************************************
version: a27ed42161ad96c53e715ca5c5e3e3fa4cff5262 Mon, 24 Apr 2023 15:41:53 -0400
****************************************************
This is the Client Portal Gateway
for any issues, please contact api@ibkr.com
and include a copy of your logs
****************************************************
https://www.interactivebrokers.com/api/doc.html
****************************************************
Open https://localhost:5000 to login
App demo is available after you login under: https://localhost:5000/demo#/
2024-05-15 16:11:11,943|I| Gateway connection established
2024-05-15 16:11:12,021|I| NO SESSION Status(running=True, session=False, connected=False, authenticated=False, competing=False, collision=False, session_id=None, server_name=None, server_version=None, expires=None)
2024-05-15 16:11:12,022|I| Authentication strategy: "B"
2024-05-15 16:11:12,022|I| No active sessions, logging in...
2024-05-15 16:11:12,022|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
2024-05-15 16:11:19,685|I| Gateway auth webpage loaded
2024-05-15 16:11:19,685|I| Login attempt number 1
2024-05-15 16:11:24,973|I| Submitting the form
2024-05-15 16:11:40,374|E| Timeout reached when waiting for authentication. The website seems to not be loaded correctly. Consider increasing IBEAM_PAGE_LOAD_TIMEOUT.
Website URL: https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on

Exception:
  File "/srv/ibeam/ibeam_starter.py", line 168, in <module>
    success, shutdown, status = client.start_and_authenticate()
  File "/srv/ibeam/src/gateway_client.py", line 53, in start_and_authenticate
    success, shutdown, status = self.strategy_handler.try_authenticating(request_retries=request_retries)
  File "/srv/ibeam/src/handlers/strategy_handler.py", line 85, in try_authenticating
    return self._authentication_strategy_B(status, request_retries)
  File "/srv/ibeam/src/handlers/strategy_handler.py", line 140, in _authentication_strategy_B
    return self._log_in(status)
  File "/srv/ibeam/src/handlers/strategy_handler.py", line 151, in _log_in
    success, shutdown = self.login_handler.login()
  File "/srv/ibeam/src/handlers/login_handler.py", line 462, in login
    self.handle_timeout_exception(e, targets, driver, website_version, self.route_auth, self.base_url, self.outputs_dir)
  File "/srv/ibeam/src/handlers/login_handler.py", line 443, in login
    self.attempt(targets, wait_and_identify_trigger, driver)
  File "/srv/ibeam/src/handlers/login_handler.py", line 367, in attempt
    trigger, target = self.step_login(targets, wait_and_identify_trigger, driver, self.secrets_handler.account, self.secrets_handler.password, self.secrets_handler.key, self.presubmit_buffer)
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/srv/ibeam/src/handlers/login_handler.py", line 188, in step_login
    trigger, target = wait_and_identify_trigger(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/srv/ibeam/src/handlers/login_handler.py", line 67, in _wait_and_identify_trigger
    trigger = WebDriverWait(driver, timeout).until(any_of(*expected_conditions))
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/support/wait.py", line 95, in until
    raise TimeoutException(message, screen, stacktrace)

  <class 'selenium.common.exceptions.TimeoutException'> Message:

2024-05-15 16:11:40,374|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7f6ba303b5d0> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="dfe2db53097b371783ab7869840bd9a4")>
2024-05-15 16:11:40,441|I| Logging in failed
2024-05-15 16:11:40,447|I| Starting maintenance with interval 60 seconds
^C2024-05-15 16:11:43,389|I| Keyboard interrupt, shutting down.

Suggest a Fix
Maybe the client portal page layout changed again?

[Voyz]

Hey @lazerlabs many thanks for checking out IBeam and introducing your own addition 👏Also thanks for the detailed report.

As for the issue you're describing, there's a very similar conversation happening with another user in this Issue: #185 I suggest you have a look and attempt to debug it in a similar manner as I describe there. Indeed, potentially IBKR could have changed something, although unfortunately it still seems to work on my end hence it's quite difficult for me to implement a fix without your help in debugging it. I suggest we continue this discussion there, unless you feel there is a substantial difference.

I noticed this behaviour while implementing an http_callback TFA handler (see my fork: https://github.com/lazerlabs/ibeam/blob/master/ibeam/src/two_fa_handlers/http_callback.py) but it happens the same with voyz/ibeam:0.5.3
(I can provide more details about how this would work, and I would send a pull request, but I wanted to test it for a while and atm I can't for this issue)

Thanks for sharing that! I'm understanding that in your setup the 2FA code is being received and parsed by some external server, and that response is then fed into this Flask server you've developed? If that is the case then while it's great to see the addition, but I don't think it would be necessary to include it in IBeam. The ExternalRequestHandler provides an identical functionality, except that instead of storing the 2FA code within the handler, the code would to be stored on that external server. Let me know if I'm missing something here though.

[lazerlabs]

Thanks for the pointer to the other issue, I'll try to debug it.

Regarding http_callback it actually works the other way round compared top ExternalRequestHandler.

http_callback spawns a web server which wait to receive the security code.

So I can automatically send the code to ibeam as soon as the SMS is received. There is one handler that does this for Android, but this works with iphone:

1. I have created a cloudflare tunnel to the ibeam instance (so I don't have to expose the web server directly). You can however forward the port on the router.
2. On my iphone where IBKR number is, I have created an automation (see the screenshots) that extract the code from the SMS and send it to the URL via a PUT method

Now, there are other way to implemement that, like using the iphone automation to send it to a dropbox file (which can have a URL) and use the ExternalRequestHandler to get it from there. But I would have to deal with existing code and delete it.
Alternatively, I could have another web server somewhere or use S3 with a TTL policy which delete the code after it's downloaded by the ExternalRequestHandler.

However I like this approach because is immediate (sms -> ibeam) and have it automatically expire after "duration".

I tested the automation for a while independently from ibeam, now I'm in the integration phase (issues aside).

[Voyz]

Ohhh! I didn't think about doing it directly from the phone. That's a very clever idea, apologies for my ignorance to this approach in the previous reply. Yeah, that could be a great addition.

Would you be up for writing a WiKi page on how to set up your phone to send the SMS to a custom URL? That would be of great help to other users if we integrated your handler to IBeam.

Great job coming up with that 👏👏

[Voyz]

@lazerlabs it seems a solution was found for the problem with authentication: #185 (comment) Can you see if this works for you too?