Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Timeout error in 0.4.4 version #140

Closed
elderanakain opened this issue May 16, 2023 · 55 comments
Closed

Timeout error in 0.4.4 version #140

elderanakain opened this issue May 16, 2023 · 55 comments
Assignees
Labels
bug Something isn't working

Comments

@elderanakain
Copy link

elderanakain commented May 16, 2023

Describe the bug
This morning, after the update to voyz/ibeam:0.4.4, a local watchtower service restarted the IBeam, and it stopped authenticating with an error, which looks like a timeout. Please, take a look at the stack trace below, as I don't know Python very well.

To Reproduce
Steps to reproduce the behavior:

  1. Pull 0.4.4 docker image
  2. Start it

Expected behavior
IBeam docker image works the same as before. I have tested quickly in the same environment with 0.4.3, and it worked just fine.

Environment
IBeam version: 0.4.4
Docker image or standalone: docker
OS: Ubuntu 22.04.2 LTS (GNU/Linux 5.15.0-71-generic x86_64) as a DigitalOcean droplet, check also on a local macOS machine

Additional context
Logs:

logs
2023-05-16 07:55:39,965|I| ############ Starting IBeam version 0.4.4 ############
2023-05-16 07:55:39,975|I| Secrets source: env
2023-05-16 07:55:39,979|I| Health server started at port=5001
2023-05-16 07:55:39,979|I| Environment variable 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': 1, 'REQUEST_TIMEOUT': 15, 'RESTART_FAILED_SESSIONS': True, 'RESTART_WAIT': 15, 'IBEAM_HEALTH_SERVER_PORT': 5001, 'GATEWAY_BASE_URL': 'https://localhost:5000', 'ROUTE_AUTH': '/sso/Login?forwardTo=22&RL=1&ip2loc=on', 'ROUTE_USER': '/v1/api/one/user', 'ROUTE_VALIDATE': '/v1/portal/sso/validate', 'ROUTE_REAUTHENTICATE': '/v1/portal/iserver/reauthenticate?force=true', 'ROUTE_AUTH_STATUS': '/v1/api/iserver/auth/status', 'ROUTE_TICKLE': '/v1/api/tickle', 'ROUTE_LOGOUT': '/v1/api/logout', 'USER_NAME_EL': None, 'PASSWORD_EL': 'password', 'SUBMIT_EL': 'button.btn.btn-lg.btn-primary', 'ERROR_EL': None, 'SUCCESS_EL_TEXT': 'Client login succeeds', 'OAUTH_TIMEOUT': 30, 'PAGE_LOAD_TIMEOUT': 60, 'ERROR_SCREENSHOTS': False, 'MAX_FAILED_AUTH': 6, 'MAX_IMMEDIATE_ATTEMPTS': 10, 'IBKEY_PROMO_EL_CLASS': 'ibkey-promo-skip', 'TWO_FA_EL_ID': 'twofactbase', 'TWO_FA_NOTIFICATION_EL': 'login-step-notification', 'TWO_FA_INPUT_EL_ID': 'chlginput', 'TWO_FA_HANDLER': None, 'STRICT_TWO_FA_CODE': True, 'TWO_FA_SELECT_EL_ID': 'sf_select', 'TWO_FA_SELECT_TARGET': 'IB Key'}
2023-05-16 07:55:39,980|I| Gateway not found, starting new one...
2023-05-16 07:55:39,980|I| Note that the Gateway log below may display "Open https://localhost:5000 to login" - ignore this command.
2023-05-16 07:55:39,981|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
2023-05-16 07:55:40,984|I| Gateway started with pid: 12
2023-05-16 07:55:40,987|I| Cannot ping Gateway. Retrying for another 20 seconds
2023-05-16 07:55:41,992|I| Cannot ping Gateway. Retrying for another 19 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
2023-05-16 07:55:42,995|I| Cannot ping Gateway. Retrying for another 18 seconds
 -> mount demo on /demo
Java Version: 11.0.18
****************************************************
version: 485dc2d762781c4ff3954ac4fb66a9469a1405f7 Mon, 20 Mar 2023 14:39:35 -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#/
2023-05-16 07:55:45,650|I| Gateway connection established
2023-05-16 07:55:45,983|I| No active sessions, logging in...
2023-05-16 07:55:45,985|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
2023-05-16 07:55:47,264|E| Error encountered during authentication
Traceback (most recent call last):
  File "/srv/ibeam/src/authenticate.py", line 243, in authenticate_gateway
    driver = start_driver(base_url, driver_path)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/srv/ibeam/src/authenticate.py", line 432, in start_driver
    driver = new_chrome_driver(driver_path)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/srv/ibeam/src/authenticate.py", line 64, in new_chrome_driver
    driver = webdriver.Chrome(driver_path, options=options)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/chrome/webdriver.py", line 76, in __init__
    RemoteWebDriver.__init__(
  File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 157, in __init__
    self.start_session(capabilities, browser_profile)
  File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 252, in start_session
    response = self.execute(Command.NEW_SESSION, parameters)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 319, in execute
    response = self.command_executor.execute(driver_command, params)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/remote_connection.py", line 374, in execute
    return self._request(command_info[0], url, body=data)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/remote_connection.py", line 397, in _request
    resp = self._conn.request(method, url, body=body, headers=headers)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/urllib3/_request_methods.py", line 118, in request
    return self.request_encode_body(
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/urllib3/_request_methods.py", line 217, in request_encode_body
    return self.urlopen(method, url, **extra_kw)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/urllib3/poolmanager.py", line 422, in urlopen
    conn = self.connection_from_host(u.host, port=u.port, scheme=u.scheme)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/urllib3/poolmanager.py", line 303, in connection_from_host
    return self.connection_from_context(request_context)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/urllib3/poolmanager.py", line 328, in connection_from_context
    return self.connection_from_pool_key(pool_key, request_context=request_context)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/urllib3/poolmanager.py", line 351, in connection_from_pool_key
    pool = self._new_pool(scheme, host, port, request_context=request_context)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/urllib3/poolmanager.py", line 265, in _new_pool
    return pool_cls(host, port, **request_context)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 196, in __init__
    timeout = Timeout.from_float(timeout)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/urllib3/util/timeout.py", line 190, in from_float
    return Timeout(read=timeout, connect=timeout)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/urllib3/util/timeout.py", line 119, in __init__
    self._connect = self._validate_timeout(connect, "connect")
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/urllib3/util/timeout.py", line 156, in _validate_timeout
    raise ValueError(
ValueError: Timeout value connect was <object object at 0x7f9f97ef47e0>, but it must be an int, float or None.
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/srv/ibeam/src/authenticate.py", line 412, in authenticate_gateway
    raise RuntimeError('Error encountered during authentication') from e
RuntimeError: Error encountered during authentication
2023-05-16 07:55:47,274|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7f9f9798a310> | Driver: None
2023-05-16 07:55:47,288|I| Authentication process failed
@elderanakain elderanakain added the bug Something isn't working label May 16, 2023
@elderanakain elderanakain changed the title Timeout error in 4.4 version Timeout error in 0.4.4 version May 16, 2023
@eswark18
Copy link

same issue, it worked yesterday though

@Voyz Voyz self-assigned this May 16, 2023
@Voyz
Copy link
Owner

Voyz commented May 16, 2023

Thanks for reporting @elderanakain @eswark18 and for the detailed issue description 👍

It seems that there's an issue with the selenium installation. Please try using voyz/ibeam:0.4.5-rc1 in which I've updated the package versions, and let me know if it fixes the problem

@elderanakain
Copy link
Author

elderanakain commented May 16, 2023

@Voyz Thank you for the quick reply!
However, it seems that it didn't solve the issue, but the stack trace is a bit different:

logs
 2023-05-16 18:52:22,669|I| ############ Starting IBeam version 0.4.5-rc1 ############
 2023-05-16 18:52:22,693|I| Secrets source: env
 2023-05-16 18:52:22,705|I| Health server started at port=5001
 2023-05-16 18:52:22,706|I| Environment variable 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': 1, 'REQUEST_TIMEOUT': 15, 'RESTART_FAILED_SESSIONS': True, 'RESTART_WAIT': 15, 'IBEAM_HEALTH_SERVER_PORT': 5001, 'GATEWAY_BASE_URL': 'https://localhost:5000', 'ROUTE_AUTH': '/sso/Login?forwardTo=22&RL=1&ip2loc=on', 'ROUTE_USER': '/v1/api/one/user', 'ROUTE_VALIDATE': '/v1/portal/sso/validate', 'ROUTE_REAUTHENTICATE': '/v1/portal/iserver/reauthenticate?force=true', 'ROUTE_AUTH_STATUS': '/v1/api/iserver/auth/status', 'ROUTE_TICKLE': '/v1/api/tickle', 'ROUTE_LOGOUT': '/v1/api/logout', 'USER_NAME_EL': None, 'PASSWORD_EL': 'password', 'SUBMIT_EL': 'button.btn.btn-lg.btn-primary', 'ERROR_EL': None, 'SUCCESS_EL_TEXT': 'Client login succeeds', 'OAUTH_TIMEOUT': 30, 'PAGE_LOAD_TIMEOUT': 60, 'ERROR_SCREENSHOTS': False, 'MAX_FAILED_AUTH': 6, 'MAX_IMMEDIATE_ATTEMPTS': 10, 'IBKEY_PROMO_EL_CLASS': 'ibkey-promo-skip', 'TWO_FA_EL_ID': 'twofactbase', 'TWO_FA_NOTIFICATION_EL': 'login-step-notification', 'TWO_FA_INPUT_EL_ID': 'chlginput', 'TWO_FA_HANDLER': None, 'STRICT_TWO_FA_CODE': True, 'TWO_FA_SELECT_EL_ID': 'sf_select', 'TWO_FA_SELECT_TARGET': 'IB Key'}
 2023-05-16 18:52:22,710|I| Gateway not found, starting new one...
 2023-05-16 18:52:22,710|I| Note that the Gateway log below may display "Open https://localhost:5000 to login" - ignore this command.
 2023-05-16 18:52:22,710|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
 2023-05-16 18:52:23,722|I| Gateway started with pid: 24
 2023-05-16 18:52:23,733|I| Cannot ping Gateway. Retrying for another 20 seconds
 2023-05-16 18:52:24,739|I| Cannot ping Gateway. Retrying for another 19 seconds
 2023-05-16 18:52:25,744|I| Cannot ping Gateway. Retrying for another 18 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
 2023-05-16 18:52:26,750|I| Cannot ping Gateway. Retrying for another 17 seconds
  -> mount demo on /demo
 Java Version: 11.0.18
 ****************************************************
 version: 485dc2d762781c4ff3954ac4fb66a9469a1405f7 Mon, 20 Mar 2023 14:39:35 -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#/
 2023-05-16 18:52:27,755|I| Cannot ping Gateway. Retrying for another 16 seconds
 2023-05-16 18:52:31,779|I| Gateway connection established
 2023-05-16 18:52:32,233|I| No active sessions, logging in...
 2023-05-16 18:52:32,234|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
 127.0.0.1 - - [16/May/2023 18:52:51] "GET /readyz HTTP/1.1" 503 -
 127.0.0.1 - - [16/May/2023 18:53:22] "GET /readyz HTTP/1.1" 503 -
 2023-05-16 18:53:33,588|E| Error encountered during authentication
 Traceback (most recent call last):
   File "/srv/ibeam/src/authenticate.py", line 243, in authenticate_gateway
     driver = start_driver(base_url, driver_path)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   File "/srv/ibeam/src/authenticate.py", line 445, in start_driver
     raise e
   File "/srv/ibeam/src/authenticate.py", line 433, in start_driver
     driver = new_chrome_driver(driver_path)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   File "/srv/ibeam/src/authenticate.py", line 64, in new_chrome_driver
     driver = webdriver.Chrome(driver_path, options=options)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/chrome/webdriver.py", line 84, in __init__
     super().__init__(
   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/chromium/webdriver.py", line 104, in __init__
     super().__init__(
   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 286, in __init__
     self.start_session(capabilities, browser_profile)
   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 378, in start_session
     response = self.execute(Command.NEW_SESSION, parameters)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 440, in execute
     self.error_handler.check_response(response)
   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/errorhandler.py", line 245, in check_response
     raise exception_class(message, screen, stacktrace)
 selenium.common.exceptions.WebDriverException: Message: chrome not reachable
 Stacktrace:
 #0 0x0040007337f9 <unknown>
 #1 0x0040006d33b3 <unknown>
 #2 0x00400041ade1 <unknown>
 #3 0x0040004095b1 <unknown>
 #4 0x004000441784 <unknown>
 #5 0x00400043d99a <unknown>
 #6 0x00400043a89a <unknown>
 #7 0x00400047800a <unknown>
 #8 0x004000472c93 <unknown>
 #9 0x004000444ce4 <unknown>
 #10 0x0040004464d2 <unknown>
 #11 0x0040006ff542 <unknown>
 #12 0x00400070ece7 <unknown>
 #13 0x00400070e9e4 <unknown>
 #14 0x00400071313a <unknown>
 #15 0x00400070f5b9 <unknown>
 #16 0x0040006f4e00 <unknown>
 #17 0x0040007265d2 <unknown>
 #18 0x004000726778 <unknown>
 #19 0x00400073ea1f <unknown>
 #20 0x004002445fa3 start_thread
 #21 0x00400323306f clone
 
 
 The above exception was the direct cause of the following exception:
 
 Traceback (most recent call last):
   File "/srv/ibeam/src/authenticate.py", line 413, in authenticate_gateway
     raise RuntimeError('Error encountered during authentication') from e
 RuntimeError: Error encountered during authentication
 2023-05-16 18:53:33,610|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x400438fd10> | Driver: None
 2023-05-16 18:53:33,620|I| Authentication process failed
 2023-05-16 18:53:33,644|I| Starting maintenance with interval 60 seconds

@Voyz
Copy link
Owner

Voyz commented May 16, 2023

Thanks for reporting back @elderanakain! Snap, that's an annoying error. It seems to just pop up randomly, and I can't figure out what causes it. Can you give it a shot to launch it a few more times and see if it is persistent in your setup?

@elderanakain
Copy link
Author

elderanakain commented May 16, 2023

@Voyz, I have tried to run it several times on my local machine, and it is very persistent. I happened every time after each restart, and if I leave it running to get to the next maintenance cycle.

I have used the DEBUG log level - it didn't reveal anything new, IBEAM_ERROR_SCREENSHOTS: True also didn't produce anything.

Not sure if it is helpful, but here are logs from the IBKR GW:

logs
21:42:47.312 INFO  vert.x-eventloop-thread-0 GatewayHttpProxy     :  -> mount demo on /demo
21:42:47.394 INFO  vert.x-eventloop-thread-0 GatewayVerticle      : version: 485dc2d762781c4ff3954ac4fb66a9469a1405f7 Mon, 20 Mar 2023 14:39:35 -0400
21:42:47.395 INFO  vert.x-eventloop-thread-0 GatewayVerticle      : Java Version: 11.0.18
21:42:51.513 INFO  vert.x-eventloop-thread-0 BaseServiceProxy     : -> GET /sso/Login?forwardTo=22&RL=1&ip2loc=US,200|1600ms
21:42:51.519 INFO  vert.x-eventloop-thread-0 CookieManager        : set cookies [XYZAB_AM.LOGIN=""; Domain=.ibkr.com; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Path=/;Secure;SameSite=None, XYZAB=""; Domain=.ibkr.com; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Path=/;Secure;SameSite=None, USERID=""; Domain=.ibkr.com; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Path=/;Secure;SameSite=None, URL_PARAM="forwardTo=22&RL=1&ip2loc=US"; Version=1; Domain=.ibkr.com; Path=/;Secure, JSESSIONID=33670ADBC766A97DE7CB3EDF33407598.ny5wwwdam1-internet; Path=/sso; HttpOnly;Secure;SameSite=None]
21:42:51.531 DEBUG vert.x-eventloop-thread-0 BaseServiceProxy     : Remapping Set-cookies [XYZAB_AM.LOGIN=""; Domain=.ibkr.com; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Path=/;Secure;SameSite=None, XYZAB=""; Domain=.ibkr.com; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Path=/;Secure;SameSite=None, USERID=""; Domain=.ibkr.com; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Path=/;Secure;SameSite=None, URL_PARAM="forwardTo=22&RL=1&ip2loc=US"; Version=1; Domain=.ibkr.com; Path=/;Secure, JSESSIONID=33670ADBC766A97DE7CB3EDF33407598.ny5wwwdam1-internet; Path=/sso; HttpOnly;Secure;SameSite=None] -> 
21:42:51.646 ERROR vert.x-eventloop-thread-0 ConnectionBase       : java.nio.channels.ClosedChannelException
21:42:51.655 ERROR vert.x-eventloop-thread-0 ConnectionBase       : java.nio.channels.ClosedChannelException
21:42:51.664 ERROR vert.x-eventloop-thread-0 ConnectionBase       : java.nio.channels.ClosedChannelException
21:42:51.664 ERROR vert.x-eventloop-thread-0 ConnectionBase       : java.nio.channels.ClosedChannelException
21:42:51.944 INFO  vert.x-eventloop-thread-0 BaseServiceProxy     : -> GET /v1/api/tickle,401|159ms
21:43:12.131 INFO  vert.x-eventloop-thread-0 BaseServiceProxy     : -> GET /v1/api/tickle,401|167ms

Could you please provide some direction on where the issue is, so I will try to look into this as well? Is it somehow related to a selenium version, chromedriver?

@Voyz
Copy link
Owner

Voyz commented May 16, 2023

Thanks for testing that for me. I must admit, I'm kinda blind at this point. I've found some resources metioning adding options.add_argument('--disable-features=VizDisplayCompositor') to chrome driver options. I did that and pushed voyz/ibeam:0.4.5-rc2 - let me know if that helps.

Also, can you test that version on your server as well as on your dev machine and see if it persists there?

While this isn't going to make it any better for you at this moment, I'm observing that there isn't more reports coming in of this issue. I'm imagining this may affect only a small amount of users.

@elderanakain
Copy link
Author

elderanakain commented May 17, 2023

Thank you for the details. I will see what I can do to make it work on my local machine.

However, the new RC has worked just fine on my Linux server 🎉 thank you for the quick fix!

Still have the same issue on my macOS machine, but I agree that it looks like it affects a small number of users, and macOS is definitely not the primary target platform :)
From local machine:

logs
 2023-05-17 16:05:48,482|I| Environment variable configuration:
 {'INPUTS_DIR': '/srv/inputs/', 'OUTPUTS_DIR': '/srv/outputs', 'GATEWAY_DIR': '/srv/clientportal.gw', 'CHROME_DRIVER_PATH': '/usr/bin/chromedriver', 'GATEWAY_STARTUP': 60, 'GATEWAY_PROCESS_MATCH': 'ibgroup.web.core.clientportal.gw.GatewayStart', 'MAINTENANCE_INTERVAL': 60, 'SPAWN_NEW_PROCESSES': False, 'LOG_LEVEL': 'DEBUG', 'LOG_TO_FILE': True, 'LOG_FORMAT': '%(asctime)s|%(levelname)-.1s| %(message)s', 'REQUEST_RETRIES': 1, 'REQUEST_TIMEOUT': 15, 'RESTART_FAILED_SESSIONS': True, 'RESTART_WAIT': 15, 'IBEAM_HEALTH_SERVER_PORT': 5001, 'GATEWAY_BASE_URL': 'https://localhost:5000', 'ROUTE_AUTH': '/sso/Login?forwardTo=22&RL=1&ip2loc=on', 'ROUTE_USER': '/v1/api/one/user', 'ROUTE_VALIDATE': '/v1/portal/sso/validate', 'ROUTE_REAUTHENTICATE': '/v1/portal/iserver/reauthenticate?force=true', 'ROUTE_AUTH_STATUS': '/v1/api/iserver/auth/status', 'ROUTE_TICKLE': '/v1/api/tickle', 'ROUTE_LOGOUT': '/v1/api/logout', 'USER_NAME_EL': None, 'PASSWORD_EL': 'password', 'SUBMIT_EL': 'button.btn.btn-lg.btn-primary', 'ERROR_EL': None, 'SUCCESS_EL_TEXT': 'Client login succeeds', 'OAUTH_TIMEOUT': 30, 'PAGE_LOAD_TIMEOUT': 60, 'ERROR_SCREENSHOTS': False, 'MAX_FAILED_AUTH': 6, 'MAX_IMMEDIATE_ATTEMPTS': 10, 'IBKEY_PROMO_EL_CLASS': 'ibkey-promo-skip', 'TWO_FA_EL_ID': 'twofactbase', 'TWO_FA_NOTIFICATION_EL': 'login-step-notification', 'TWO_FA_INPUT_EL_ID': 'chlginput', 'TWO_FA_HANDLER': None, 'STRICT_TWO_FA_CODE': True, 'TWO_FA_SELECT_EL_ID': 'sf_select', 'TWO_FA_SELECT_TARGET': 'IB Key'}
 2023-05-17 16:05:48,486|I| Gateway not found, starting new one...
 2023-05-17 16:05:48,487|I| Note that the Gateway log below may display "Open https://localhost:5000 to login" - ignore this command.
 2023-05-17 16:05:48,487|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
 2023-05-17 16:05:49,501|I| Gateway started with pid: 24
 2023-05-17 16:05:49,502|D| HTTPS (unverified) request to: https://localhost:5000
 2023-05-17 16:05:49,514|I| Cannot ping Gateway. Retrying for another 60 seconds
 2023-05-17 16:05:50,517|D| HTTPS (unverified) request to: https://localhost:5000
 2023-05-17 16:05:50,525|I| Cannot ping Gateway. Retrying for another 59 seconds
 2023-05-17 16:05:51,526|D| HTTPS (unverified) request to: https://localhost:5000
 2023-05-17 16:05:51,531|I| Cannot ping Gateway. Retrying for another 58 seconds
 2023-05-17 16:05:52,532|D| HTTPS (unverified) request to: https://localhost:5000
 2023-05-17 16:05:52,540|I| Cannot ping Gateway. Retrying for another 57 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
 2023-05-17 16:05:53,543|D| HTTPS (unverified) request to: https://localhost:5000
 2023-05-17 16:05:53,549|I| Cannot ping Gateway. Retrying for another 56 seconds
 2023-05-17 16:05:54,551|D| HTTPS (unverified) request to: https://localhost:5000
 2023-05-17 16:05:54,560|I| Cannot ping Gateway. Retrying for another 55 seconds
  -> mount demo on /demo
 Java Version: 11.0.18
 ****************************************************
 version: 485dc2d762781c4ff3954ac4fb66a9469a1405f7 Mon, 20 Mar 2023 14:39:35 -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#/
 2023-05-17 16:05:55,561|D| HTTPS (unverified) request to: https://localhost:5000
 2023-05-17 16:05:59,086|I| Gateway connection established
 2023-05-17 16:05:59,087|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
 2023-05-17 16:05:59,455|I| No active sessions, logging in...
 2023-05-17 16:05:59,455|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
 2023-05-17 16:06:16,731|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
 127.0.0.1 - - [17/May/2023 16:06:17] "GET /readyz HTTP/1.1" 503 -
 2023-05-17 16:06:47,257|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
 127.0.0.1 - - [17/May/2023 16:06:47] "GET /readyz HTTP/1.1" 503 -
 2023-05-17 16:07:01,016|E| Error encountered during authentication
 Traceback (most recent call last):
   File "/srv/ibeam/src/authenticate.py", line 244, in authenticate_gateway
     driver = start_driver(base_url, driver_path)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   File "/srv/ibeam/src/authenticate.py", line 446, in start_driver
     raise e
   File "/srv/ibeam/src/authenticate.py", line 434, in start_driver
     driver = new_chrome_driver(driver_path)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   File "/srv/ibeam/src/authenticate.py", line 65, in new_chrome_driver
     driver = webdriver.Chrome(driver_path, options=options)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/chrome/webdriver.py", line 84, in __init__
     super().__init__(
   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/chromium/webdriver.py", line 104, in __init__
     super().__init__(
   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 286, in __init__
     self.start_session(capabilities, browser_profile)
   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 378, in start_session
     response = self.execute(Command.NEW_SESSION, parameters)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 440, in execute
     self.error_handler.check_response(response)
   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/errorhandler.py", line 245, in check_response
     raise exception_class(message, screen, stacktrace)
 selenium.common.exceptions.WebDriverException: Message: chrome not reachable
 Stacktrace:
 #0 0x0040007337f9 <unknown>
 #1 0x0040006d33b3 <unknown>
 #2 0x00400041ade1 <unknown>
 #3 0x0040004095b1 <unknown>
 #4 0x004000441784 <unknown>
 #5 0x00400043d99a <unknown>
 #6 0x00400043a89a <unknown>
 #7 0x00400047800a <unknown>
 #8 0x004000472c93 <unknown>
 #9 0x004000444ce4 <unknown>
 #10 0x0040004464d2 <unknown>
 #11 0x0040006ff542 <unknown>
 #12 0x00400070ece7 <unknown>
 #13 0x00400070e9e4 <unknown>
 #14 0x00400071313a <unknown>
 #15 0x00400070f5b9 <unknown>
 #16 0x0040006f4e00 <unknown>
 #17 0x0040007265d2 <unknown>
 #18 0x004000726778 <unknown>
 #19 0x00400073ea1f <unknown>
 #20 0x004002445fa3 start_thread
 #21 0x00400323306f clone
 
 
 The above exception was the direct cause of the following exception:
 
 Traceback (most recent call last):
   File "/srv/ibeam/src/authenticate.py", line 414, in authenticate_gateway
     raise RuntimeError('Error encountered during authentication') from e
 RuntimeError: Error encountered during authentication
 2023-05-17 16:07:01,035|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x4004742a10> | Driver: None
 2023-05-17 16:07:01,044|I| Authentication process failed
 2023-05-17 16:07:01,062|I| Starting maintenance with interval 60 seconds
 2023-05-17 16:07:17,941|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
 127.0.0.1 - - [17/May/2023 16:07:18] "GET /readyz HTTP/1.1" 503 -

@Voyz
Copy link
Owner

Voyz commented May 17, 2023

Gotcha, thanks for confirming. I'm still gutted it's breaking up on your dev station. Let me know if I can help you brainstorm about this.

Just FYI - I've pushed master branch, so it now has those most recent fixes in case you'd be interested in pulling and fixing things first hand.

@bfoz
Copy link

bfoz commented May 17, 2023

I'm also seeing what appears to be a timeout of some sort using the 0.4.4 release (not the latest fixes)

Attaching to ibeam
ibeam    | WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
ibeam    | WARNING: All illegal access operations will be denied in a future release
ibeam    | 2023-05-17 23:01:09,769|I| Gateway started with pid: 13
ibeam    | 2023-05-17 23:01:09,772|I| Cannot ping Gateway. Retrying for another 20 seconds
ibeam    |  -> mount demo on /demo
ibeam    | Java Version: 11.0.18
ibeam    | ****************************************************
ibeam    | version: 485dc2d762781c4ff3954ac4fb66a9469a1405f7 Mon, 20 Mar 2023 14:39:35 -0400
ibeam    | ****************************************************
ibeam    | This is the Client Portal Gateway
ibeam    | for any issues, please contact api@ibkr.com
ibeam    | and include a copy of your logs
ibeam    | ****************************************************
ibeam    | https://www.interactivebrokers.com/api/doc.html
ibeam    | ****************************************************
ibeam    | Open https://localhost:5000 to login
ibeam    | App demo is available after you login under: https://localhost:5000/demo#/
ibeam    | 2023-05-17 23:01:11,464|I| Gateway connection established
ibeam    | 2023-05-17 23:01:11,706|I| No active sessions, logging in...
ibeam    | 2023-05-17 23:01:11,706|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
ibeam    | 2023-05-17 23:01:12,798|E| Error encountered during authentication
ibeam    | Traceback (most recent call last):
ibeam    |   File "/srv/ibeam/src/authenticate.py", line 243, in authenticate_gateway
ibeam    | 2023-05-17 23:01:12,811|I| Authentication process failed
ibeam    | 2023-05-17 23:01:12,816|I| Starting maintenance with interval 60 seconds
ibeam    | 2023-05-17 23:02:12,817|I| Maintenance
ibeam    | 2023-05-17 23:02:13,796|I| No active sessions, logging in...
ibeam    | 2023-05-17 23:02:13,797|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
ibeam    | 2023-05-17 23:02:14,888|E| Error encountered during authentication
ibeam    | Traceback (most recent call last):
ibeam    |   File "/srv/ibeam/src/authenticate.py", line 243, in authenticate_gateway
ibeam    |     driver = start_driver(base_url, driver_path)
ibeam    |              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/srv/ibeam/src/authenticate.py", line 432, in start_driver
ibeam    |     driver = new_chrome_driver(driver_path)
ibeam    |              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/srv/ibeam/src/authenticate.py", line 64, in new_chrome_driver
ibeam    |     driver = webdriver.Chrome(driver_path, options=options)
ibeam    |              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/chrome/webdriver.py", line 76, in __init__
ibeam    |     RemoteWebDriver.__init__(
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 157, in __init__
ibeam    |     self.start_session(capabilities, browser_profile)
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 252, in start_session
ibeam    |     response = self.execute(Command.NEW_SESSION, parameters)
ibeam    |                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 319, in execute
ibeam    |     response = self.command_executor.execute(driver_command, params)
ibeam    |                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/remote_connection.py", line 374, in execute
ibeam    |     return self._request(command_info[0], url, body=data)
ibeam    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/remote_connection.py", line 397, in _request
ibeam    |     resp = self._conn.request(method, url, body=body, headers=headers)
ibeam    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/urllib3/_request_methods.py", line 118, in request
ibeam    |     return self.request_encode_body(
ibeam    |            ^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/urllib3/_request_methods.py", line 217, in request_encode_body
ibeam    |     return self.urlopen(method, url, **extra_kw)
ibeam    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/urllib3/poolmanager.py", line 422, in urlopen
ibeam    |     conn = self.connection_from_host(u.host, port=u.port, scheme=u.scheme)
ibeam    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/urllib3/poolmanager.py", line 303, in connection_from_host
ibeam    |     return self.connection_from_context(request_context)
ibeam    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/urllib3/poolmanager.py", line 328, in connection_from_context
ibeam    |     return self.connection_from_pool_key(pool_key, request_context=request_context)
ibeam    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/urllib3/poolmanager.py", line 351, in connection_from_pool_key
ibeam    |     pool = self._new_pool(scheme, host, port, request_context=request_context)
ibeam    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/urllib3/poolmanager.py", line 265, in _new_pool
ibeam    |     return pool_cls(host, port, **request_context)
ibeam    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 196, in __init__
ibeam    |     timeout = Timeout.from_float(timeout)
ibeam    |               ^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/urllib3/util/timeout.py", line 190, in from_float
ibeam    |     return Timeout(read=timeout, connect=timeout)
ibeam    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/urllib3/util/timeout.py", line 119, in __init__
ibeam    |     self._connect = self._validate_timeout(connect, "connect")
ibeam    |                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/urllib3/util/timeout.py", line 156, in _validate_timeout
ibeam    |     raise ValueError(
ibeam    | ValueError: Timeout value connect was <object object at 0x7fac7de54590>, but it must be an int, float or None.
ibeam    | 
ibeam    | The above exception was the direct cause of the following exception:
ibeam    | 
ibeam    | Traceback (most recent call last):
ibeam    |   File "/srv/ibeam/src/authenticate.py", line 412, in authenticate_gateway
ibeam    |     raise RuntimeError('Error encountered during authentication') from e
ibeam    | RuntimeError: Error encountered during authentication
ibeam    | 2023-05-17 23:02:14,891|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7fac7c46fbd0> | Driver: None
ibeam    | 2023-05-17 23:02:14,902|I| Authentication process failed

After that, it seems to get stuck in a loop...

ibeam    | 2023-05-17 23:03:12,818|I| Maintenance
ibeam    | 2023-05-17 23:03:13,027|I| No active sessions, logging in...
ibeam    | 2023-05-17 23:03:13,028|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
ibeam    | 2023-05-17 23:03:14,117|E| Error encountered during authentication
ibeam    | Traceback (most recent call last):
ibeam    |   File "/srv/ibeam/src/authenticate.py", line 243, in authenticate_gateway
ibeam    |              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/srv/ibeam/src/authenticate.py", line 432, in start_driver
ibeam    |     driver = new_chrome_driver(driver_path)
ibeam    |              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 319, in execute
ibeam    |     response = self.command_executor.execute(driver_command, params)
ibeam    |     conn = self.connection_from_host(u.host, port=u.port, scheme=u.scheme)
ibeam    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |     pool = self._new_pool(scheme, host, port, request_context=request_context)
ibeam    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/urllib3/poolmanager.py", line 265, in _new_pool
ibeam    | The above exception was the direct cause of the following exception:
ibeam    | 
ibeam    | Traceback (most recent call last):
ibeam    | 2023-05-17 23:03:14,128|I| Authentication process failed

@stephas
Copy link

stephas commented May 18, 2023

Thanks for testing that for me. I must admit, I'm kinda blind at this point. I've found some resources metioning adding options.add_argument('--disable-features=VizDisplayCompositor') to chrome driver options. I did that and pushed voyz/ibeam:0.4.5-rc2 - let me know if that helps.

Also, can you test that version on your server as well as on your dev machine and see if it persists there?

While this isn't going to make it any better for you at this moment, I'm observing that there isn't more reports coming in of this issue. I'm imagining this may affect only a small amount of users.

I came across ibeam a few days ago and ran into the timeout issue.

FWIW On linux, your change for 0.4.5-rc2 (in addition to increasing startup and page load timeouts) allowed me to authenticate (including IB key.. experience). This resolved the first error bfoz posted above, not sure about the second log.

@bfoz
Copy link

bfoz commented May 18, 2023

I just pulled 0.4.5-rc2 and the timeout seems to be solved, but now it's stuck in a "success" loop:

ibeam    | ****************************************************
ibeam    | This is the Client Portal Gateway
ibeam    | for any issues, please contact api@ibkr.com
ibeam    | and include a copy of your logs
ibeam    | ****************************************************
ibeam    | https://www.interactivebrokers.com/api/doc.html
ibeam    | ****************************************************
ibeam    | Open https://localhost:5000 to login
ibeam    | App demo is available after you login under: https://localhost:5000/demo#/
ibeam    | 2023-05-18 22:52:39,231|I| Gateway connection established
ibeam    | 2023-05-18 22:52:39,470|I| No active sessions, logging in...
ibeam    | 2023-05-18 22:52:39,471|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
ibeam    | 2023-05-18 22:52:44,097|I| Gateway auth webpage loaded
ibeam    | 2023-05-18 22:52:44,097|I| Login attempt number 1
ibeam    | 2023-05-18 22:52:49,320|I| Submitting the form
ibeam    | 2023-05-18 22:52:50,187|I| Credentials correct, but Gateway requires notification two-factor authentication.
ibeam    | 2023-05-18 22:52:55,746|I| Webpage displayed "Client login succeeds"
ibeam    | 2023-05-18 22:52:57,747|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7fd95d65bb10> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="009ab6c8650327e6669133d9a6dc30d6")>
ibeam    | 2023-05-18 22:52:57,811|I| Authentication process succeeded
ibeam    | 2023-05-18 22:53:00,941|E| Gateway session active but not authenticated
ibeam    | 2023-05-18 22:53:00,941|I| Logging out and restarting the Gateway
ibeam    | 2023-05-18 22:53:01,206|I| Gateway logout successful
ibeam    | 2023-05-18 22:53:01,328|I| Gateway session found but not authenticated, authenticating...
ibeam    | 2023-05-18 22:53:01,329|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
ibeam    | 2023-05-18 22:53:03,365|I| Gateway auth webpage loaded
ibeam    | 2023-05-18 22:53:03,365|I| Login attempt number 1
ibeam    | 2023-05-18 22:53:08,587|I| Submitting the form
ibeam    | 2023-05-18 22:53:09,457|I| Credentials correct, but Gateway requires notification two-factor authentication.
ibeam    | 2023-05-18 22:53:14,611|I| Webpage displayed "Client login succeeds"
ibeam    | 2023-05-18 22:53:16,612|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7fd95b8e5110> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="64271428c33e354203d1b23cd042ba7a")>
ibeam    | 2023-05-18 22:53:16,662|I| Authentication process succeeded
ibeam    | 2023-05-18 22:53:19,795|E| Gateway session active but not authenticated
ibeam    | 2023-05-18 22:53:19,795|I| Logging out and restarting the Gateway
ibeam    | 2023-05-18 22:53:19,933|I| Gateway logout successful
ibeam    | 2023-05-18 22:53:20,055|I| Gateway session found but not authenticated, authenticating...
ibeam    | 2023-05-18 22:53:20,055|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
ibeam    | 2023-05-18 22:53:22,061|I| Gateway auth webpage loaded
ibeam    | 2023-05-18 22:53:22,061|I| Login attempt number 1
ibeam    | 2023-05-18 22:53:27,305|I| Submitting the form
ibeam    | 2023-05-18 22:53:28,175|I| Credentials correct, but Gateway requires notification two-factor authentication.
ibeam    | 2023-05-18 22:53:43,370|E| Timeout reached when waiting for authentication. Consider increasing IBEAM_PAGE_LOAD_TIMEOUT. Error: "" at   File "/srv/ibeam/src/authenticate.py", line 337, in authenticate_gateway    trigger = WebDriverWait(driver, var.OAUTH_TIMEOUT).until(              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    | 2023-05-18 22:53:43,370|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7fd95b8f0190> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="c4efa7a2b0423a3315d1d067d1bff874")>
ibeam    | 2023-05-18 22:53:43,422|I| Authentication process failed
ibeam    | 2023-05-18 22:53:43,428|I| Starting maintenance with interval 60 seconds

The loop restarts after 60 seconds.

@bfoz
Copy link

bfoz commented May 18, 2023

Eventually it worked 🤷‍♂️

ibeam    | 2023-05-18 22:58:07,495|I| Gateway running and authenticated

@stephas
Copy link

stephas commented May 18, 2023

Eventually it worked 🤷‍♂️

ibeam    | 2023-05-18 22:58:07,495|I| Gateway running and authenticated

Nice! This was where I cursed and wished TOTP was a valid MFA method for IBKR. And increased my IBEAM_PAGE_LOAD_TIMEOUT

@Voyz
Copy link
Owner

Voyz commented May 19, 2023

hey @bfoz @stephas and others: can you check if these issue happen to you on 0.4.4-rc6, 0.4.4-rc3 or 0.4.3?

@vldmarton
Copy link

vldmarton commented May 22, 2023

@Voyz hi there, I just tried 0.4.4-rc6 and I'm getting following error (running on Mac M1):

2023-05-22 20:32:32 2023-05-22 18:32:32,646|I| No active sessions, logging in...
2023-05-22 20:32:32 2023-05-22 18:32:32,647|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
2023-05-22 20:33:34 2023-05-22 18:33:34,572|E| Error encountered during authentication
2023-05-22 20:33:34 Traceback (most recent call last):
2023-05-22 20:33:34   File "/srv/ibeam/src/authenticate.py", line 243, in authenticate_gateway
2023-05-22 20:33:34     driver = start_driver(base_url, driver_path)
2023-05-22 20:33:34              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-05-22 20:33:34   File "/srv/ibeam/src/authenticate.py", line 444, in start_driver
2023-05-22 20:33:34     raise e
2023-05-22 20:33:34   File "/srv/ibeam/src/authenticate.py", line 432, in start_driver
2023-05-22 20:33:34     driver = new_chrome_driver(driver_path)
2023-05-22 20:33:34              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-05-22 20:33:34   File "/srv/ibeam/src/authenticate.py", line 64, in new_chrome_driver
2023-05-22 20:33:34     driver = webdriver.Chrome(driver_path, options=options)
2023-05-22 20:33:34              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-05-22 20:33:34   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/chrome/webdriver.py", line 76, in __init__
2023-05-22 20:33:34     RemoteWebDriver.__init__(
2023-05-22 20:33:34   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 157, in __init__
2023-05-22 20:33:34     self.start_session(capabilities, browser_profile)
2023-05-22 20:33:34   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 252, in start_session
2023-05-22 20:33:34     response = self.execute(Command.NEW_SESSION, parameters)
2023-05-22 20:33:34                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-05-22 20:33:34   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 321, in execute
2023-05-22 20:33:34     self.error_handler.check_response(response)
2023-05-22 20:33:34   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/errorhandler.py", line 242, in check_response
2023-05-22 20:33:34     raise exception_class(message, screen, stacktrace)
2023-05-22 20:33:34 selenium.common.exceptions.WebDriverException: Message: chrome not reachable
2023-05-22 20:33:34 
2023-05-22 20:33:34 
2023-05-22 20:33:34 The above exception was the direct cause of the following exception:
2023-05-22 20:33:34 
2023-05-22 20:33:34 Traceback (most recent call last):
2023-05-22 20:33:34   File "/srv/ibeam/src/authenticate.py", line 412, in authenticate_gateway
2023-05-22 20:33:34     raise RuntimeError('Error encountered during authentication') from e
2023-05-22 20:33:34 RuntimeError: Error encountered during authentication
2023-05-22 20:33:34 2023-05-22 18:33:34,592|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x4003ecb8d0> | Driver: None
2023-05-22 20:33:34 2023-05-22 18:33:34,625|I| Authentication process failed
2023-05-22 20:33:34 2023-05-22 18:33:34,651|I| Starting maintenance with interval 60 seconds
2023-05-22 20:34:34 2023-05-22 18:34:34,670|I| Maintenance
2023-05-22 20:34:35 2023-05-22 18:34:35,075|I| Gateway running and authenticated
2023-05-22 20:35:34 2023-05-22 18:35:34,677|I| Maintenance
2023-05-22 20:35:35 2023-05-22 18:35:35,149|I| Gateway running and authenticated

0.4.3 works fine for me, but I can see substantial differences between the API gateway versions, I believe 0.4.3 has gateway version from 2018 and 0.4.4 has one from 2023. Would it be possible to do a re-release of 0.4.3 with a newer API gateway? (or is that what's going on with 0.4.4 and I'm asking stupid questions?)

Also, for some reason, on 0.4.3 I don't have to do manual login, but on 0.4.4 onwards I have to open the authentication page and log in - is that because of the newer version of IBKR Api Gateway or because of the chrome issue?

@vldmarton
Copy link

vldmarton commented May 23, 2023

A quick update, took the code from main, updated Dockerfile to:
FROM python:3.11.2-slim-buster -> FROM python:3.11.3-slim-bullseye

As bullseye supports newer versions of chrome and chromedriver (the jump was significant, I believe it was from version 80-something to a hundred something), it was possible to use the newest version and that fixed the chrome not reachable issue.

I also downloaded the newest version of API gateway, but I don't think that made a difference.

And as someone mentioned in one of the other issues, I changed IBKR API endpoint in conf.yaml file.
"https://api.ibkr.com" -> "https://6.api.ibkr.com"
(as it was mentioned before, this number can range from 1 to 8 and I did not have luck with 8 or 7, but 6 did the trick. Although, I don't think this is a long-term solution.

Anyway, now the API gateway only took 2 attempts to log me in, and after spending hours trying different versions of chrome, selenium, api gateway and base docker image, I'm going to call it a success. Hopefully it helps someone.

@Voyz someone mentioned it elsewhere that it would be great if ibeam could automagically try various API endpoints to see which will work. You mentioned that it would bring a risk of having to change conf.yaml file on the fly. Could you elaborate more? What is the risk?

@Voyz
Copy link
Owner

Voyz commented May 23, 2023

Hey @vldmarton superb digging, thanks for helping push this issue forward 👏🥳

I'm quite surprised that updating the Python version would work. Nevertheless, I've just pushed the voyz/ibeam:0.4.5-rc3 with that change - could you guys let me know if that works? As a side note: I've also updated some logging on that version to make timeout errors more verbose.

@Voyz
Copy link
Owner

Voyz commented May 23, 2023

@Voyz someone mentioned it elsewhere that it would be great if ibeam could automagically try various API endpoints to see which will work. You mentioned that it would bring a risk of having to change conf.yaml file on the fly. Could you elaborate more? What is the risk?

My thoughts are as follows:

  • We're modifying a crucial configuration file on the fly. If we do something wrong there, we'd stop the system from working, which is not great.
  • We're reading/writing a file that's used live in the system. Once again, if something goes wrong here (I/O for example), we're left with a corrupted file that's difficult to recover.

Therefore, it is an added risk and complexity, hence trying out other methods first sounds like a better idea to me.

We could have a 'source' version of the conf.yaml and then use that to write out a live version. Each time we'd want to wrangle the server URL, we could copy the 'source' file and modify it only then. This would reduce the risk of messing things up.

All in all though, it sounds like a bit of a project to take on. If someone would like to, feel free to contribute a PR with this addition.

@vldmarton
Copy link

Thank you, but we should really be thanking you instead, you did an incredible amount of work here for us.

I'm quite surprised that updating the Python version would work. I've just pushed the voyz/ibeam:0.4.5-rc3 with that change - could you guys let me know if that works? As a side note: I've also updated some logging on that version to make timeout errors more verbose.

Unfortunately that doesn't work for me. I don't think it was the python version that did the trick. Other than the python version, I also changed the base image from buster (debian 10) to bullseye (debian 11). That allowed the newer versions of chrome and chromedriver to be downloaded. Did you make that change in 0.4.5-rc3 as well? If yes, perhaps the fact that I'm running an amd64 image on darwin is causing the issue...

We could have a 'source' version of the conf.yaml and then use that to write out a live version. Each time we'd want to wrangle the server URL, we could copy the 'source' file and modify it only then. This would reduce the risk of messing things up.

Either that, or we could rename conf.yaml to something else (conf-1.yaml), create 7 additional versions of the file (2,3,....,8) with different API endpoints and the startup process in python (function start_gateway()) would be changed to take an optional argument (conf file path) that would be fed to subprocess args. I know having 8 files in total with almost identical contents is not the best idea but this way we wouldn't have to manipulate the file content at all.

All in all though, it sounds like a bit of a project to take on. If someone would like to, feel free to contribute a PR with this addition.

It really sucks that IBKR cannot fix this issue themselves (we can only implement workarounds, and that's far from ideal). I will try to put some code together tomorrow but I'm not as good with Python as you, so don't expect much 😆

@Voyz
Copy link
Owner

Voyz commented May 23, 2023

Aw thanks for the kind words 🤭

Other than the python version, I also changed the base image from buster (debian 10) to bullseye (debian 11)

Yes, I've changed that too. The current version is python:3.11.3-slim-bullseye, can you double check that's correct in the DOCKERFILE?

If yes, perhaps the fact that I'm running an amd64 image on darwin is causing the issue...

Perhaps, yeah. The only other thing I can think of is the version of the Gateway that got upgraded to the July 2022 version in 0.4.4. Wanna see if an older version before that commit would help solve the issue? 49d2bf1

Either that, or we could rename conf.yaml to something else (conf-1.yaml), create 7 additional versions of the file

Cool idea! Some things to consider:

  • What happens when user updates the original conf.yaml? I'm thinking we'd need to write out all these 7 files each time IBeam is started, and make it clear that they can't be modified during runtime.
  • I think a useful improvement would be to wrangle the server we try to talk to each time an authentication fails (trying 1,2,3 ...6, 7, 1, 2, 3...) without having to specify the version through the env vars. Otherwise, this would be equivalent of modifying the conf.yaml manually each time you'd restart the container.
  • Indeed, that's gonna increase complexity and could be error prone. My biggest fear is that all that work will be for nothing, as IBKR never clearly stated that doing so will solve all the problems. They mentioned it as a workaround, kind of a 'try it, it may work'.

I will try to put some code together tomorrow but I'm not as good with Python as you, so don't expect much

Amazing, thanks! And I'm here to help! Feel free to submit a WIP PR as you're working and we can iterate on ideas together 🤜🤛

@vldmarton
Copy link

Yes, I've changed that too. The current version is python:3.11.3-slim-bullseye, can you double check that's correct in the DOCKERFILE?

Yep, that's correct, I also checked the container image and it matches the Dockerfile, so no issue there.

Perhaps, yeah. The only other thing I can think of is the version of the Gateway that got upgraded to the July 2022 version in 0.4.4. Wanna see if an older version before that commit would help solve the issue? 49d2bf1

We don't even get to the point where gateway could be the problem, and apologies for not mentioning what is the current issue now. I'm just reading my previous answers and I said that it's not working for me, but I didn't say WHAT is not working 😞 The issue is still chrome not reachable. I tried to check versions of packages installed in the image - this is the output:

$ chromedriver --version
ChromeDriver 113.0.5672.126 (c541687b21a73452ab403e2dced7033ddc97ee9d-refs/branch-heads/5672@{#1202})
$ chromium --version
Error: Can't open display: 
$ chrome --version
/bin/sh: 17: chrome: not found

I'm not sure which one of these is even correct, but 1.) the Can't open display: is strange and 2.) I cannot install chrome inside the running container because I can't obtain root privileges. Can you fire up a container on your side please and let me know if you get the same output? If yes, there is something wrong with the chrome/chromium installation in rc3.

My biggest fear is that all that work will be for nothing, as IBKR never clearly stated that doing so will solve all the problems. They mentioned it as a workaround, kind of a 'try it, it may work'.

Yep, I don't like it very much either. My worry is that we will implement conf file rotation for 8 API endpoints and in the next release they will implement a new, load balanced API endpoint, which will make our solution redundant. 🤣 Maybe a support ticket would be the number one thing to do, and in case we don't manage to "beat" a solution out of them (and not just a recommendation), we could move forward here. I'll get on that first.

@vldmarton
Copy link

@Voyz I created the IBKR support ticket, but it's going to take some time to get a response. In the meantime, I looked on the internet and found other github project with the same aim and with the same problem - it's an interesting read for sure:
areed1192/interactive-broker-python-api/issues/2

TLDR: Do not rely on the /iserver/auth/status (docs) endpoint to return authenticated: true, but check if you're able to do some actions on the account instead. The flow:

  1. do a login
  2. Ignore the answer (so even if you get authenticated:false from the endpoint, you don't consider the login attempt failed)
  3. do some GETs (f.e. get porftolio, get live orders, or anything else)
  4. if it fails, go through login again, if not, you're authenticated

@Voyz
Copy link
Owner

Voyz commented May 24, 2023

I tried to check versions of packages installed in the image - this is the output:

Yes, that seems to be fine. We don't use chrome anymore, we use chromium. And when you try to launch it from the container it complains about not being able to connect to a display, which sounds fine to me.

root@ffea9bd21020:/srv/ibeam# chromium --no-sandbox
[167:167:0524/155236.915464:ERROR:browser_main_loop.cc(1386)] Unable to open X display.

Can you fire up a container on your side please and let me know if you get the same output?

I'm getting a similar output, but I also am getting similar output on 0.4.3. I'd say this is expected behaviour.

I'm seeing the following on 0.4.3:

root@ffea9bd21020:/srv/ibeam# chromium --version
Chromium 90.0.4430.212 built on Debian 10.9, running on Debian 10.4
root@ffea9bd21020:/srv/ibeam# chromedriver --version
ChromeDriver 90.0.4430.212 (e3cd97fc771b893b7fd1879196d1215b622c2bed-refs/branch-heads/4430@{#1429})

And on 0.4.4:

root@32e8f901ac2e:/srv/ibeam# chromium --version
find: /root/.config/chromium/Crash Reports/pending/: No such file or directory
Chromium 113.0.5672.126 built on Debian 11.7, running on Debian 11.7
root@32e8f901ac2e:/srv/ibeam# chromedriver --version
ChromeDriver 113.0.5672.126 (c541687b21a73452ab403e2dced7033ddc97ee9d-refs/branch-heads/5672@{#1202})

I suppose one indication that things aren't right is that on your machine the chromium --version produced the Error: Can't open display:.

Maybe a support ticket would be the number one thing to do,

Great to see you tried this. Let us know what they say.

TLDR: Do not rely on the /iserver/auth/status (docs) endpoint to return authenticated: true,

Right, I can see that, great digging 👍

Seeing that this is from an unofficial source and quite speculative, I'm not sure whether this would be a methodology we'd want to follow. My thoughts are:

  • the API docs state a contradictory thing, and it's generally a good idea to use these as the source of truth. I can see the benefit of ignoring it here, but there's an argument here that we should expect this endpoint to work.
  • the authenticated:false returns false for some reason. I'd be worried that potentially some endpoints would work and some wouldn't, and we couldn't guarantee whether it's one or the other.
  • I sort of prefer a system that is more binary in that sense. We either have 100% confidence that we're authenticated, or we have 0% confidence and have to reauthenticate - even if it means looping over and over. To have this 'sorta unauthenticated, but maybe yes, so let's see if it works' state would not feel quite right.

I'd feel that prompting IBKR to fix things would be the right way to go here.

@andreimcristof
Copy link

Hello, just pulled latest image today, and hit a similar problem on Windows 11. Error is:

ibeam  |   File "/opt/venv/lib/python3.11/site-packages/urllib3/util/timeout.py", line 119, in __init__
ibeam  |     self._connect = self._validate_timeout(connect, "connect")
ibeam  |                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam  |   File "/opt/venv/lib/python3.11/site-packages/urllib3/util/timeout.py", line 156, in _validate_timeout       
ibeam  |     raise ValueError(
ibeam  | ValueError: Timeout value connect was <object object at 0x7f754db947e0>, but it must be an int, float or None.
ibeam  |
ibeam  | The above exception was the direct cause of the following exception:
ibeam  |
ibeam  | Traceback (most recent call last):
ibeam  |   File "/srv/ibeam/src/authenticate.py", line 412, in authenticate_gateway

Also, my docker compose is:

services:
  ibeam:
    image: voyz/ibeam
    container_name: ibeam
    ports:
      - 5000:5000
    environment:
      - IBEAM_ACCOUNT=${IBEAM_ACCOUNT}
      - IBEAM_PASSWORD=${IBEAM_PASSWORD}

If there are any suggestions that can be tried, please throw one in my direction. Cheers,

@Voyz
Copy link
Owner

Voyz commented May 27, 2023

@andreimcristof thanks for joining in and sharing the details. Can you try voyz/ibeam:0.4.5-rc3 and see if that helps? I think that error in particular was due to Selenium version not being up to date.

@andreimcristof
Copy link

andreimcristof commented May 27, 2023

@Voyz Thank you very much for your speedy help. Tried it, and... spot on - seeing Authentication process succeeded made my Saturday. However, I had to input 2FA code twice. Although it seems to work afterwards. Thank you.
Since this is a release candidate as I understand, I should expect that the image will not be available soon anymore as the fix will be pushed to main image voyz/ibeam?
Also, if I want to make requests to the IB API, through IBeam, from a localhost web app, do I understand correctly that the default TLS certificate will not work, and I need to generate the certificates and provide them ?

later edit - please ignore the questions. Made everything work :)

@Voyz
Copy link
Owner

Voyz commented May 30, 2023

@vldmarton many thanks for sharing this here. This bit got my curiosity

It is a common occurrence to log in twice as the initial login will terminate any previously active session and during the second login, you can proceed with the login process as you typically would.

I don't quite understand it, I've got two interpretations of this. Give a 👍 or 👎 if you believe it's the former or the latter.

👍 Does it mean that logging in twice will somehow log us out?
👎 Or do they recommend for us to be logging in twice?

When the maintenance schedule is running, do you only call /tickle endpoint or also /sso/validate?

Only tickle. They previously said we need to run only one of these endpoints. The docs only speaks of tickle:

A Client Portal API brokerage session will timeout if no requests are received within a period of 5 minutes. In order to prevent the session from timing out, the endpoint /tickle should be called on a regular basis. It is recommended to call this endpoint approximately every minute.

In either case, not sure how calling validate would help. Am I missing something where this could be useful? I'm thinking that when things go badly, the result of tickle is irrelevant anyway, as the biggest issues come from their servers telling us that Client login succeeds indicating a successful login, but then the authenticate still is false, or receiving the 503, or the 2FA resulting in failed for no clear reason. But that's just my take; point it out if I'm not seeing some application of calling /sso/validate.

I actually asked them about the 1-8 nodes as well and interestingly they did not respond to that. From the response, it seems like the repetitive authentication (even if it's 10 times in a row) is an expected behavior 🤣

Yeah... I wouldn't really have much to comment on this 🤷‍♂️😔

@Voyz
Copy link
Owner

Voyz commented May 30, 2023

I've just published voyz/ibeam:0.4.5 and updated the latest. Hoping this will solve the issues with 0.4.4 👍 Let me know if you get a chance to test it out

@vldmarton
Copy link

By the way, just out of curiosity, I added an extra piece of logging to confirm if we really depend on the authenticated: true response (wanted to see if it matters or we can go by without it) - first line is the standard output, the other two lines are mine output:

2023-05-30 19:24:17 2023-05-30 17:24:17,127|E| Gateway session active but not authenticated
2023-05-30 19:24:17 2023-05-30 17:24:17,128|I| Trying to get AAPL ticker information to see if really not authenticated
2023-05-30 19:24:18 2023-05-30 17:24:18,192|I| {'error': 'Init session first', 'statusCode': 400}

So, unfortunately, looks like we do have to get authenticated: true otherwise it's not even possible to do basic things.


☝️ Does it mean that logging in twice will somehow log us out?
✌️ Or do they recommend for us to be logging in twice?

What he says has actually happened to me multiple times when running API gateway directly on my computer. I started the gateway and I was logged into paper account on my phone as well. I had to open browser, log in once, which returned me to the login page and I had to log in agan. After the second attempt, it went fine.

Similar situation is happening when I open client portal from my laptop browser and log in, and then log into the same acc from my phone. The browser on my laptop will say that there is another session and that my actions are limited. There is a Sign in button next to it. After clicking on Sign in, it repeats the warning and wants me to click the "Sign in" button again. After I do that, I'm allowed to view my portfolio, open trades, etc.

Therefore, it's starting to seem to me that the 2-attempt login is a normal thing in IBKR. I'm not sure though why in some cases it's necessary to do it more than twice.

In either case, not sure how calling validate would help.

I'm mixing two different topics here I'm afraid, and I forgot to describe the latter. This is what happens in my container all the time - I'm dotting out logs to save space and it's also important to point out that it happens randomly (sometimes there isn't a problem for 4+ hours and sometimes it happens twice within 30 minutes):

2023-05-30 19:24:39 2023-05-30 17:24:39,177|I| Gateway running and authenticated
2023-05-30 19:24:55 2023-05-30 17:24:55,088|I| Maintenance
2023-05-30 19:24:55 2023-05-30 17:24:55,575|I| Gateway running and authenticated
2023-05-30 19:25:55 2023-05-30 17:25:55,083|I| Maintenance
.......
2023-05-30 20:14:55 2023-05-30 18:14:55,742|I| Gateway running and authenticated
2023-05-30 20:15:55 2023-05-30 18:15:55,092|I| Maintenance
2023-05-30 20:15:55 2023-05-30 18:15:55,646|I| Gateway session found but not authenticated, authenticating...
2023-05-30 20:15:55 2023-05-30 18:15:55,647|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
2023-05-30 20:16:02 2023-05-30 18:16:02,143|I| Gateway auth webpage loaded
2023-05-30 20:16:02 2023-05-30 18:16:02,143|I| Login attempt number 1
.......
2023-05-30 20:16:12 2023-05-30 18:16:12,691|I| Authentication process succeeded
2023-05-30 20:16:16 2023-05-30 18:16:16,224|E| Gateway session active but not authenticated
2023-05-30 20:16:17 2023-05-30 18:16:17,148|I| Logging out and restarting the Gateway
2023-05-30 20:16:17 2023-05-30 18:16:17,760|I| Gateway logout successful
2023-05-30 20:16:18 2023-05-30 18:16:18,279|I| Gateway session found but not authenticated, authenticating...

So, as you can see, there is some issue with the Gateway because after approx. an hour it decided that the session is logged out for some reason. So, perhaps calling both /tickle and /sso/validate would solve this issue. The reason this is an issue is because in my trading system I want to open trades 2 minutes before the market closes. If shit hits the fan during those 2 minutes, I will miss out on a trade and setups that I trade don't happen very often, so reliability is very important for me (perhaps I shouldn't have chosen IBKR 😢 )

If there is an issue with the session, I want to know about it ASAP, can't wait 60 seconds for the maintenance window. So, here's an idea:

  • call tickle and sso/validate every 60 seconds to see if it fixes the random outages
  • call authentication status endpoint every 5 seconds and rerun auth if failed

I've just published voyz/ibeam:0.4.5 and updated the latest. Hoping this will solve the issues with 0.4.4 👍 Let me know if you get a chance to test it out

Looks very stable buddy 🥳 not sure what you did but no more crashes. Although, it had to go through the auth process 3 times to do a successful login, but tbh, at this point I don't care anymore, I'm just happy it succeeded - I guess I have to appreciate the little things 🤣 I'll keep it running at night and see what happened during the night. For now, I'm attaching logs of the login attemps: ibeam-045.log

@Voyz
Copy link
Owner

Voyz commented May 30, 2023

@vldmarton Thanks for sharing your results 👍 And thanks for casting light on that 2-log in, I get your point now. Okay, well I guess IBeam will do that automatically. It does correlate with some results I'm seeing.

So, perhaps calling both /tickle and /sso/validate would solve this issue.

In all fairness, let's give it a shot, we've got the code to call /sso/validate in place already. I've pushed voyz/ibeam:0.4.6-rc1 with that change. Feel free to give it a shot.

If shit hits the fan during those 2 minutes, I will miss out on a trade and setups that I trade don't happen very often, so reliability is very important for me (perhaps I shouldn't have chosen IBKR 😢 )

😬 I feel for you, yeah, reliability is key in this case. Possibly request secondary account (or even a tertiary one), and keep several instances of IBeam active and open. Then hide it behind a load balancer and switch between them depending on the health status.

If there is an issue with the session, I want to know about it ASAP, can't wait 60 seconds for the maintenance window.

Just in case you haven't considered it, you can change IBEAM_MAINTENANCE_INTERVAL env var to make a shorter maintenance window. I can't think of a reason why you couldn't set it to a low value like 10 seconds.

call authentication status endpoint every 5 seconds and rerun auth if failed

Note that the whole reauth process can take longer than 5 seconds, so you may be stuck in a re-auth loop if you do this check too often.

Looks very stable buddy 🥳

Very cool, thanks for confirming! 🚀

@vldmarton
Copy link

In all fairness, let's give it a shot, we've got the code to call /sso/validate in place already. I've pushed voyz/ibeam:0.4.6-rc1 with that change. Feel free to give it a shot.

Thanks for the new version, I will run it now and get back to you in a few hours.

Possibly request secondary account (or even a tertiary one), and keep several instances of IBeam active and open. Then hide it behind a load balancer and switch between them depending on the health status.

That's actually a good idea, thanks, but the problem is that I would have to split my capital to three accounts and that would reduce my profit by the number of accounts. I was thinking yesterday about running 3 instances of IBEAM a storing authentication state somewhere, so that there is always at least 1 instance which is successfully authenticated and as soon as things go wrong with it, it removes the state file and one of the other two take over. For now, I keep it in my head, because this might become a very time-consuming project and again, it's just a workaround for something that should work without it.

Just in case you haven't considered it, you can change IBEAM_MAINTENANCE_INTERVAL env var to make a shorter maintenance window. I can't think of a reason why you couldn't set it to a low value like 10 seconds.

Thanks, will give that a go with the 0.4.6-rc1.


I'm also attaching a continuation of the log file from yesterday - it's version 0.4.5, started at 20:34 and still running until now. Unfortunately there is a bunch of weird things happening. 😢 ibeam-455-2.log

@vldmarton
Copy link

vldmarton commented May 31, 2023

@Voyz 0.4.6 gives me chrome not reachable error and at this point I'm pretty sure that it's an architecture problem:

Screenshot 2023-05-31 at 06 50 51
  • 0.4.5 didn't give me the AMD64 warning and chrome worked
  • my local build also did not (obviously) and chrome also worked
  • but the 0.4.6 release candidate causes issues.

I'm not sure what the release process is (I've never pushed images to dockerhub), but looks like the rc versions are not built for multi-platform.

@corbinhudson
Copy link

IBKR having ANOTHER auth issue on their end w/ client portal API this morning, just off the phone w/ them

@JackD111
Copy link
Contributor

@Voyz Starting this morning i had timeout issues Timeout reached when waiting for authentication. Consider increasing IBEAM_PAGE_LOAD_TIMEOUT. I've previously used 0.4.0 for ages now and just upgraded to latest. issue has resolved now
image

Didn't look deeper in what you changed but thanks, works for me now.

@vldmarton
Copy link

I'm also attaching a continuation of the log file from yesterday - it's version 0.4.5, started at 20:34 and still running until now. Unfortunately there is a bunch of weird things happening. 😢 ibeam-455-2.log

A small update, it's not clear to me how it was possible to get blocked by the scheduler for such a long time, it must be some frozen process that blocks the whole script (it would be interesting to see what blocked it). So, in the meanwhile, I'm testing with IBEAM_SPAWN_NEW_PROCESSES=true so that each maintenance call is executed separately, and IBEAM_LOG_LEVEL=DEBUG to perhaps see more information in case it happens again. Will post my results in the evening.

@vldmarton
Copy link

Okay, so it looks like the random skipped scheduler runs are not caused by the ibeam code, but rather by my Mac. I don't know what's going on in the background, but it seems like it was putting processes to sleep even though the system is not sleeping and screen is on. I will test it on a linux server some time in the near future, but I'm currently busy with other things.

@Voyz
Copy link
Owner

Voyz commented Jun 1, 2023

@vldmarton

That's actually a good idea, thanks, but the problem is that I would have to split my capital to three accounts and that would reduce my profit by the number of accounts.

As far as I understand these are separate logins to the same account. I'd double check it, but I think you wouldn't need to split it into three accounts.

0.4.6 gives me chrome not reachable error and at this point I'm pretty sure that it's an architecture problem:

Right are you running it on arm chip? Yeah the -rc* releases I only build for amd. That would explain the chrome issues potentially. Just pushed an updated version of 0.4.6-rc1 built for multiplatform - lemme know how that works.

@Voyz
Copy link
Owner

Voyz commented Jun 1, 2023

@corbinhudson

IBKR having ANOTHER auth issue on their end w/ client portal API this morning, just off the phone w/ them

Can you share what was the issue an what was their response? If it was unrelated to the topics described in this issue it may be a good idea to open a separate issue

@Voyz
Copy link
Owner

Voyz commented Jun 1, 2023

@vldmarton

Okay, so it looks like the random skipped scheduler runs are not caused by the ibeam code, but rather by my Mac.

Interesting! Can you share how did you figure that out?

I will test it on a linux server some time in the near future,

That's a good idea, keep us posted

@elderanakain
Copy link
Author

@Voyz Sorry for the long no reply. I can confirm that the latest version works fine on both machines. Thanks a lot for the fix 🎉

@migoohao
Copy link

migoohao commented Jun 2, 2023

@Voyz

If authenticate: false, why not use /iserver/reauthenticate and wait about 15s?

In my remote server, I use IBeam to keep gateway alive.
If my app found IB gateway authenticated: false, it will call /iserver/reauthenticate immediately.
This helps IBeam break the login loop.
If I do not start my app, IBeam is stuck in the login loop...

@vldmarton
Copy link

Okay, so it looks like the random skipped scheduler runs are not caused by the ibeam code, but rather by my Mac.

Interesting! Can you share how did you figure that out?

After it has happened multiple times during the same test run, I kind of just noticed that it happens when I don't use my computer for a longer period of time (20-30 minutes). I have sleep mode (and all other optimizations) turned off, I did that specifically to do this test, but still, it was happening, and it was only happening when I was away from my laptop.

I will test it on a linux server some time in the near future,

That's a good idea, keep us posted

I've been extremely busy lately so I still didn't have time for it yet, but I hope I can get back to it as soon as possible.

@andreimcristof
Copy link

  1. Try endpoint "/logout" and endpoint "/reauthenticate" several times to achieve the Authenticated: true.

The fact that this is an official statement from IBKR sounds like there is some very strange design with the Authentication procedure.

I find it amusing, or half amusing / half concerning that a company that manages people's money, actually advises that several attempts are required in order to receive Authenticated: true status. They also don't state how many attempts, and just stating "several" introduces anxiety that they don't really have a grasp on the problem at all.

Authentication should have 100% predictable outcome. But I might not understand the whole complexity of their system, it might be a legit solution to a much deeper problem.

I have also had major issues logging into Client Portal itself (the web app, so nothing API related) where, after entering 2FA code, it just flat out freezes on browser. I have to click back and retry and hope it works. At some point this just stops working entirely, so I have to do Empty cache and hard reload and then redo authentication again.

Reading through this thread in detail it seems like IBeam elegantly works around and solves some of the shortcomings of IBKR, but those shortcomings should not exist in the first place.

@vldmarton
Copy link

You're absolutely right.

IBKR has multiple products (TWS, API, mobile app, client portal). Judging by the appearance of TWS, it's very possible that the legacy code (the absolute core - session handling included) is about a 100 years old and would be too hard to rewrite (modernize) in such a way where all of those products would still work. At the same time, creating a modernized version of the core and a modernized version of all of the products would be equally hard (and expensive) and clearly IBKR is holding onto the "if it ain't broke don't fix it" methodology.

Although, I've read somewhere that they're developing a new desktop application, which should replace TWS in the future. So there's little hope. Of course, it depends on what they decide to do, because they can still build it on the top of the same, old legacy code.

@bfoz
Copy link

bfoz commented Jun 6, 2023

I'm using 0.4.5 and still seeing lots of errors. It seems to be stuck in a successful login loop again.

ibeam    | 2023-06-06 00:08:13,676|I| Login attempt number 1
ibeam    | 2023-06-06 00:08:18,968|I| Submitting the form
ibeam    | 2023-06-06 00:08:22,987|I| Webpage displayed "Client login succeeds"
ibeam    | 2023-06-06 00:08:24,987|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7f48d1e65b50> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="a1d868568dbcda0d6b29898706325997")>
ibeam    | 2023-06-06 00:08:25,031|I| Authentication process succeeded
ibeam    | 2023-06-06 00:08:28,164|E| Gateway session active but not authenticated
ibeam    | 2023-06-06 00:08:28,164|I| Logging out and restarting the Gateway
ibeam    | 2023-06-06 00:08:28,286|I| Gateway logout successful
ibeam    | 2023-06-06 00:08:28,409|I| Gateway session found but not authenticated, authenticating...
ibeam    | 2023-06-06 00:08:28,410|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
ibeam    | 2023-06-06 00:08:35,231|I| Gateway auth webpage loaded
ibeam    | 2023-06-06 00:08:35,231|I| Login attempt number 1
ibeam    | 2023-06-06 00:08:40,499|I| Submitting the form
ibeam    | 2023-06-06 00:08:56,105|E| Timeout reached searching for website elements, but the website seems to be loaded correctly. It is possible the setup is incorrect. 
ibeam    | Website version: 2 
ibeam    | DOM elements searched for: {'USER_NAME_EL': 'username', 'PASSWORD_EL': 'password', 'SUBMIT_EL': 'button.btn.btn-lg.btn-primary', 'ERROR_EL': 'xyz-errormessage', 'SUCCESS_EL_TEXT': 'Client login succeeds', 'IBKEY_PROMO_EL_CLASS': 'ibkey-promo-skip', 'TWO_FA_EL_ID': 'twofactbase', 'TWO_FA_NOTIFICATION_EL': 'login-step-notification', 'TWO_FA_INPUT_EL_ID': 'chlginput', 'TWO_FA_SELECT_EL_ID': 'sf_select'}. 
ibeam    | Exception:
ibeam    |   File "/srv/ibeam/ibeam_starter.py", line 94, in <module>
ibeam    |     success, shutdown = client.start_and_authenticate()
ibeam    |   File "/srv/ibeam/src/gateway_client.py", line 332, in start_and_authenticate
ibeam    |     success, shutdown = self.try_authenticating(request_retries=request_retries)
ibeam    |   File "/srv/ibeam/src/gateway_client.py", line 274, in try_authenticating
ibeam    |     return self.try_authenticating(request_retries=request_retries)
ibeam    |   File "/srv/ibeam/src/gateway_client.py", line 274, in try_authenticating
ibeam    |     return self.try_authenticating(request_retries=request_retries)
ibeam    |   File "/srv/ibeam/src/gateway_client.py", line 274, in try_authenticating
ibeam    |     return self.try_authenticating(request_retries=request_retries)
ibeam    |   File "/srv/ibeam/src/gateway_client.py", line 256, in try_authenticating
ibeam    |     success, shutdown = self._authenticate()
ibeam    |   File "/srv/ibeam/src/gateway_client.py", line 228, in _authenticate
ibeam    |     return authenticate_gateway(driver_path=self.driver_path,
ibeam    |   File "/srv/ibeam/src/authenticate.py", line 306, in authenticate_gateway
ibeam    |     trigger = WebDriverWait(driver, var.OAUTH_TIMEOUT).until(
ibeam    |               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ibeam    |   File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/support/wait.py", line 95, in until
ibeam    |     raise TimeoutException(message, screen, stacktrace)
ibeam    | 
ibeam    |   <class 'selenium.common.exceptions.TimeoutException'> Message: 
ibeam    | 
ibeam    | 2023-06-06 00:08:56,106|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7f48d1e69010> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="afb0899b0da1999c54dc6bf63e3bda9c")>
ibeam    | 2023-06-06 00:08:56,144|I| Authentication process failed
ibeam    | 2023-06-06 00:08:56,150|I| Starting maintenance with interval 60 seconds

@Voyz
Copy link
Owner

Voyz commented Jun 9, 2023

@migoohao short answer: we never knew /iserver/reauthenticate helps like this. So thanks for sharing! 👏👏👏

I tried that endpoint in the past but it never seemed to have solved our problems so I mainly ignored it.

I just gave it a shot to implement it - check out voyz/ibeam:0.4.6-rc2 if you like - but unfortunately it doesn't seem to work as well as it did for you. I've included it to run directly after we detect authenticated:false, but before logging out and running another authentication attempt. If you could share some ideas on how it helped you it would be great.

See the logs below:

logs
2023-06-09 04:37:08,021|I| ############ Starting IBeam version 0.4.6-rc2 ############
2023-06-09 04:37:08,027|I| Secrets source: env
2023-06-09 04:37:08,030|I| Health server started at port=5001
2023-06-09 04:37:08,030|I| Environment variable 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': True, 'LOG_LEVEL': 'DEBUG', 'LOG_TO_FILE': True, 'LOG_FORMAT': '%(asctime)s|%(levelname)-.1s| %(message)s', 'REQUEST_RETRIES': 1, 'REQUEST_TIMEOUT': 15, 'RESTART_FAILED_SESSIONS': True, 'RESTART_WAIT': 15, 'IBEAM_HEALTH_SERVER_PORT': 5001, 'GATEWAY_BASE_URL': 'https://localhost:5000', 'ROUTE_AUTH': '/sso/Login?forwardTo=22&RL=1&ip2loc=on', 'ROUTE_USER': '/v1/api/one/user', 'ROUTE_VALIDATE': '/v1/portal/sso/validate', 'ROUTE_REAUTHENTICATE': '/v1/portal/iserver/reauthenticate?force=true', 'ROUTE_AUTH_STATUS': '/v1/api/iserver/auth/status', 'ROUTE_TICKLE': '/v1/api/tickle', 'ROUTE_LOGOUT': '/v1/api/logout', 'USER_NAME_EL': None, 'PASSWORD_EL': 'password', 'SUBMIT_EL': 'button.btn.btn-lg.btn-primary', 'ERROR_EL': None, 'SUCCESS_EL_TEXT': 'Client login succeeds', 'OAUTH_TIMEOUT': 15, 'PAGE_LOAD_TIMEOUT': 15, 'ERROR_SCREENSHOTS': True, 'MAX_FAILED_AUTH': 5, 'MAX_IMMEDIATE_ATTEMPTS': 10, 'IBKEY_PROMO_EL_CLASS': 'ibkey-promo-skip', 'TWO_FA_EL_ID': 'twofactbase', 'TWO_FA_NOTIFICATION_EL': 'login-step-notification', 'TWO_FA_INPUT_EL_ID': 'chlginput', 'TWO_FA_HANDLER': None, 'STRICT_TWO_FA_CODE': True, 'TWO_FA_SELECT_EL_ID': 'sf_select', 'TWO_FA_SELECT_TARGET': 'IB Key'}
2023-06-09 04:37:08,032|I| Gateway not found, starting new one...
2023-06-09 04:37:08,033|I| Note that the Gateway log below may display "Open https://localhost:5000 to login" - ignore this command.
2023-06-09 04:37:08,034|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
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.18
****************************************************
version: 485dc2d762781c4ff3954ac4fb66a9469a1405f7 Mon, 20 Mar 2023 14:39:35 -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#/
2023-06-09 04:37:09,037|I| Gateway started with pid: 13
2023-06-09 04:37:09,038|D| HTTPS (unverified) request to: https://localhost:5000
2023-06-09 04:37:09,041|I| Cannot ping Gateway. Retrying for another 20 seconds
2023-06-09 04:37:10,042|D| HTTPS (unverified) request to: https://localhost:5000
2023-06-09 04:37:11,231|I| Gateway connection established
2023-06-09 04:37:11,232|D| HTTPS (unverified) request to: https://localhost:5000/v1/portal/sso/validate
2023-06-09 04:37:11,716|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
2023-06-09 04:37:11,924|I| No active sessions, logging in...
2023-06-09 04:37:11,925|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
2023-06-09 04:37:20,850|D| Elements: {'USER_NAME_EL': 'username', 'PASSWORD_EL': 'password', 'SUBMIT_EL': 'button.btn.btn-lg.btn-primary', 'ERROR_EL': 'xyz-errormessage', 'SUCCESS_EL_TEXT': 'Client login succeeds', 'IBKEY_PROMO_EL_CLASS': 'ibkey-promo-skip', 'TWO_FA_EL_ID': 'twofactbase', 'TWO_FA_NOTIFICATION_EL': 'login-step-notification', 'TWO_FA_INPUT_EL_ID': 'chlginput', 'TWO_FA_SELECT_EL_ID': 'sf_select'}
2023-06-09 04:37:20,864|I| Gateway auth webpage loaded
2023-06-09 04:37:20,865|I| Login attempt number 1
2023-06-09 04:37:26,173|I| Submitting the form
2023-06-09 04:37:28,165|D| trigger: Client login succeeds
2023-06-09 04:37:28,180|I| Webpage displayed "Client login succeeds"
2023-06-09 04:37:30,181|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7fa647d36610> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="8dd414e0d293558c98751d1e5906beb4")>
2023-06-09 04:37:30,252|I| Authentication process succeeded
2023-06-09 04:37:33,253|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
2023-06-09 04:37:33,418|E| Gateway session active but not authenticated
2023-06-09 04:37:33,419|D| HTTPS (unverified) request to: https://localhost:5000/v1/portal/iserver/reauthenticate?force=true
2023-06-09 04:37:33,437|I| Logging out and restarting the Gateway
2023-06-09 04:37:33,437|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/logout
2023-06-09 04:37:33,688|I| Gateway logout successful
2023-06-09 04:37:33,689|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
2023-06-09 04:37:33,869|I| Gateway session found but not authenticated, authenticating...
2023-06-09 04:37:33,870|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
2023-06-09 04:37:41,271|D| Elements: {'USER_NAME_EL': 'username', 'PASSWORD_EL': 'password', 'SUBMIT_EL': 'button.btn.btn-lg.btn-primary', 'ERROR_EL': 'xyz-errormessage', 'SUCCESS_EL_TEXT': 'Client login succeeds', 'IBKEY_PROMO_EL_CLASS': 'ibkey-promo-skip', 'TWO_FA_EL_ID': 'twofactbase', 'TWO_FA_NOTIFICATION_EL': 'login-step-notification', 'TWO_FA_INPUT_EL_ID': 'chlginput', 'TWO_FA_SELECT_EL_ID': 'sf_select'}
2023-06-09 04:37:41,284|I| Gateway auth webpage loaded
2023-06-09 04:37:41,287|I| Login attempt number 1
2023-06-09 04:37:46,519|I| Submitting the form
2023-06-09 04:37:47,657|D| trigger: Client login succeeds
2023-06-09 04:37:47,672|I| Webpage displayed "Client login succeeds"
2023-06-09 04:37:49,673|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7fa647d37a50> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="d43cde6078ad1b49c7e67af922c9b0bd")>
2023-06-09 04:37:49,765|I| Authentication process succeeded
2023-06-09 04:37:52,766|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
2023-06-09 04:37:52,956|E| Gateway session active but not authenticated
2023-06-09 04:37:52,957|D| HTTPS (unverified) request to: https://localhost:5000/v1/portal/iserver/reauthenticate?force=true
2023-06-09 04:37:52,971|I| Logging out and restarting the Gateway
2023-06-09 04:37:52,972|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/logout
2023-06-09 04:37:53,158|I| Gateway logout successful
2023-06-09 04:37:53,159|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
2023-06-09 04:37:53,379|I| Gateway session found but not authenticated, authenticating...
2023-06-09 04:37:53,382|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
2023-06-09 04:38:12,740|D| Elements: {'USER_NAME_EL': 'username', 'PASSWORD_EL': 'password', 'SUBMIT_EL': 'button.btn.btn-lg.btn-primary', 'ERROR_EL': 'xyz-errormessage', 'SUCCESS_EL_TEXT': 'Client login succeeds', 'IBKEY_PROMO_EL_CLASS': 'ibkey-promo-skip', 'TWO_FA_EL_ID': 'twofactbase', 'TWO_FA_NOTIFICATION_EL': 'login-step-notification', 'TWO_FA_INPUT_EL_ID': 'chlginput', 'TWO_FA_SELECT_EL_ID': 'sf_select'}
2023-06-09 04:38:12,754|I| Gateway auth webpage loaded
2023-06-09 04:38:12,755|I| Login attempt number 1
2023-06-09 04:38:18,000|I| Submitting the form
2023-06-09 04:38:19,550|D| trigger: Client login succeeds
2023-06-09 04:38:19,564|I| Webpage displayed "Client login succeeds"
2023-06-09 04:38:21,565|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7fa647d43e90> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="0f4440d4f72b400514648bd900cb6edc")>
2023-06-09 04:38:21,661|I| Authentication process succeeded
2023-06-09 04:38:24,662|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
2023-06-09 04:38:24,804|E| Gateway session active but not authenticated
2023-06-09 04:38:24,805|D| HTTPS (unverified) request to: https://localhost:5000/v1/portal/iserver/reauthenticate?force=true
2023-06-09 04:38:24,826|I| Logging out and restarting the Gateway
2023-06-09 04:38:24,827|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/logout
2023-06-09 04:38:24,974|I| Gateway logout successful
2023-06-09 04:38:24,975|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
2023-06-09 04:38:25,292|I| Gateway session found but not authenticated, authenticating...
2023-06-09 04:38:25,293|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
2023-06-09 04:38:32,719|D| Elements: {'USER_NAME_EL': 'username', 'PASSWORD_EL': 'password', 'SUBMIT_EL': 'button.btn.btn-lg.btn-primary', 'ERROR_EL': 'xyz-errormessage', 'SUCCESS_EL_TEXT': 'Client login succeeds', 'IBKEY_PROMO_EL_CLASS': 'ibkey-promo-skip', 'TWO_FA_EL_ID': 'twofactbase', 'TWO_FA_NOTIFICATION_EL': 'login-step-notification', 'TWO_FA_INPUT_EL_ID': 'chlginput', 'TWO_FA_SELECT_EL_ID': 'sf_select'}
2023-06-09 04:38:32,731|I| Gateway auth webpage loaded
2023-06-09 04:38:32,732|I| Login attempt number 1
2023-06-09 04:38:37,974|I| Submitting the form
2023-06-09 04:38:38,973|D| trigger: Client login succeeds
2023-06-09 04:38:38,992|I| Webpage displayed "Client login succeeds"
2023-06-09 04:38:40,994|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7fa647d47e90> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="f0a57e38f746c8fdb84888fa92f341ce")>
2023-06-09 04:38:41,078|I| Authentication process succeeded
2023-06-09 04:38:44,079|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
2023-06-09 04:38:44,244|E| Gateway session active but not authenticated
2023-06-09 04:38:44,246|D| HTTPS (unverified) request to: https://localhost:5000/v1/portal/iserver/reauthenticate?force=true
2023-06-09 04:38:44,259|I| Logging out and restarting the Gateway
2023-06-09 04:38:44,260|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/logout
2023-06-09 04:38:44,405|I| Gateway logout successful
2023-06-09 04:38:44,406|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
2023-06-09 04:38:44,635|I| Gateway session found but not authenticated, authenticating...
2023-06-09 04:38:44,636|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
2023-06-09 04:38:53,688|D| Elements: {'USER_NAME_EL': 'username', 'PASSWORD_EL': 'password', 'SUBMIT_EL': 'button.btn.btn-lg.btn-primary', 'ERROR_EL': 'xyz-errormessage', 'SUCCESS_EL_TEXT': 'Client login succeeds', 'IBKEY_PROMO_EL_CLASS': 'ibkey-promo-skip', 'TWO_FA_EL_ID': 'twofactbase', 'TWO_FA_NOTIFICATION_EL': 'login-step-notification', 'TWO_FA_INPUT_EL_ID': 'chlginput', 'TWO_FA_SELECT_EL_ID': 'sf_select'}
2023-06-09 04:38:53,700|I| Gateway auth webpage loaded
2023-06-09 04:38:53,701|I| Login attempt number 1
2023-06-09 04:38:58,965|I| Submitting the form
2023-06-09 04:38:59,982|D| trigger: Client login succeeds
2023-06-09 04:38:59,998|I| Webpage displayed "Client login succeeds"
2023-06-09 04:39:01,998|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7fa647d45b90> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="882041ca8c94582cf94467d2a7e8498c")>
2023-06-09 04:39:02,084|I| Authentication process succeeded
2023-06-09 04:39:05,085|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
2023-06-09 04:39:05,232|E| Gateway session active but not authenticated
2023-06-09 04:39:05,233|D| HTTPS (unverified) request to: https://localhost:5000/v1/portal/iserver/reauthenticate?force=true
2023-06-09 04:39:05,243|I| Logging out and restarting the Gateway
2023-06-09 04:39:05,244|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/logout
2023-06-09 04:39:05,398|I| Gateway logout successful
2023-06-09 04:39:05,399|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
2023-06-09 04:39:05,600|I| Gateway session found but not authenticated, authenticating...
2023-06-09 04:39:05,601|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
2023-06-09 04:39:12,696|D| Elements: {'USER_NAME_EL': 'username', 'PASSWORD_EL': 'password', 'SUBMIT_EL': 'button.btn.btn-lg.btn-primary', 'ERROR_EL': 'xyz-errormessage', 'SUCCESS_EL_TEXT': 'Client login succeeds', 'IBKEY_PROMO_EL_CLASS': 'ibkey-promo-skip', 'TWO_FA_EL_ID': 'twofactbase', 'TWO_FA_NOTIFICATION_EL': 'login-step-notification', 'TWO_FA_INPUT_EL_ID': 'chlginput', 'TWO_FA_SELECT_EL_ID': 'sf_select'}
2023-06-09 04:39:12,709|I| Gateway auth webpage loaded
2023-06-09 04:39:12,709|I| Login attempt number 1
2023-06-09 04:39:17,957|I| Submitting the form
2023-06-09 04:39:19,011|D| trigger: Client login succeeds
2023-06-09 04:39:19,028|I| Webpage displayed "Client login succeeds"
2023-06-09 04:39:21,029|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7fa648048d50> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="b9327fee59a5a058fc349091d1b485fe")>
2023-06-09 04:39:21,115|I| Authentication process succeeded
2023-06-09 04:39:24,116|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
2023-06-09 04:39:24,266|E| Gateway session active but not authenticated
2023-06-09 04:39:24,267|D| HTTPS (unverified) request to: https://localhost:5000/v1/portal/iserver/reauthenticate?force=true
2023-06-09 04:39:24,276|I| Logging out and restarting the Gateway
2023-06-09 04:39:24,277|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/logout
2023-06-09 04:39:24,420|I| Gateway logout successful
2023-06-09 04:39:24,421|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
2023-06-09 04:39:32,231|I| Gateway session found but not authenticated, authenticating...
2023-06-09 04:39:32,232|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
2023-06-09 04:39:39,881|D| Elements: {'USER_NAME_EL': 'username', 'PASSWORD_EL': 'password', 'SUBMIT_EL': 'button.btn.btn-lg.btn-primary', 'ERROR_EL': 'xyz-errormessage', 'SUCCESS_EL_TEXT': 'Client login succeeds', 'IBKEY_PROMO_EL_CLASS': 'ibkey-promo-skip', 'TWO_FA_EL_ID': 'twofactbase', 'TWO_FA_NOTIFICATION_EL': 'login-step-notification', 'TWO_FA_INPUT_EL_ID': 'chlginput', 'TWO_FA_SELECT_EL_ID': 'sf_select'}
2023-06-09 04:39:39,896|I| Gateway auth webpage loaded
2023-06-09 04:39:39,897|I| Login attempt number 1
2023-06-09 04:39:45,159|I| Submitting the form
2023-06-09 04:39:46,170|D| trigger: Client login succeeds
2023-06-09 04:39:46,186|I| Webpage displayed "Client login succeeds"
2023-06-09 04:39:48,187|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7fa647d4e750> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="067e8532def92c6722e6b6744829e567")>
2023-06-09 04:39:48,240|I| Authentication process succeeded
2023-06-09 04:39:51,241|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/tickle
2023-06-09 04:39:51,391|I| Gateway running and authenticated.
2023-06-09 04:39:51,401|I| Starting maintenance with interval 60 seconds

@Voyz
Copy link
Owner

Voyz commented Jun 9, 2023

@andreimcristof you're making a fair point. I think it is fair to say that a lot of IBKR users find the APIs, both CP Web API and TWS API frustrating to use. I have read some IBKR code from the Gateway front-end (anyone can read it too if you wanna check my observations) and I must admit that if its quality is any indication of the overall quality of their code internally, I'm not surprised we're encountering all these errors and pain points. At the same time, I also try to err on the side of hoping that they're doing the best they can with the system they have.

And to your last point: IBeam should not exist in the first place 😅

@Voyz
Copy link
Owner

Voyz commented Jun 9, 2023

@bfoz thanks for sharing it seems to be a different problem, not the authentication loop. The website loads but fails to find the right triggers. I'd suggest you run it in debug mode and save screenshots and open a new issue.

@migoohao
Copy link

migoohao commented Jun 19, 2023

@Voyz I noticed you triggered reauthenticate, but you triggered logout immediately. IB Gateway needs about 10-15s to make "authenticated:true".
2023-06-09 04:37:33,419|D| HTTPS (unverified) request to: https://localhost:5000/v1/portal/iserver/reauthenticate?force=true
2023-06-09 04:37:33,437|I| Logging out and restarting the Gateway
2023-06-09 04:37:33,437|D| HTTPS (unverified) request to: https://localhost:5000/v1/api/logout
I think the right steps are below:

  1. trigger: Client login succeeds
  2. if authenticated: false, trigger /iserver/reauthenticate, and keep checking "authenticated" status in 15s
  3. if authenticated: true, login success
  4. if authenticated: still false, login out and try again

@Voyz
Copy link
Owner

Voyz commented Jun 19, 2023

Thanks for sharing these thoughts @migoohao - I've just pushed voyz/ibeam:0.4.6-rc3 which includes IBEAM_REAUTHENTICATE_WAIT which will cause the wait you suggested in between reauthentication and logout. This time I can see it working, although I cannot verify if that is coincidental. Can you give it a shot and let me know if it works for you too?

@Voyz
Copy link
Owner

Voyz commented Jun 26, 2023

@elderanakain I think this issue can be closed now? Or would there be anything else we'd want to discuss regarding the timeout error in 0.4.4?

@elderanakain
Copy link
Author

@Voyz Yes, definitely, the issue has been solved. Thank you!

@Voyz
Copy link
Owner

Voyz commented Jun 27, 2023

hey @elderanakain @bfoz @stephas @vldmarton @andreimcristof @JackD111 and others - there is a new WIP version v0.5.0 of IBeam that introduces a new login logic, which should help reduce some of the issues we've been struggling with.

Run the most recent voyz/ibeam:0.5.0-rc* tag of v0.5.0 and set IBEAM_AUTHENTICATION_STRATEGY to B.

See #147 for more details and report any observations directly there.

Thanks 🙏

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

10 participants