ibeam: Timeout error in 0.4.4 version
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:
- Pull
0.4.4docker image - 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
About this issue
- Original URL
- State: closed
- Created a year ago
- Reactions: 3
- Comments: 55 (24 by maintainers)
I’m also seeing what appears to be a timeout of some sort using the 0.4.4 release (not the latest fixes)
After that, it seems to get stuck in a loop…
@Voyz Starting this morning i had timeout issues
Timeout reached when waiting for authentication. Consider increasing IBEAM_PAGE_LOAD_TIMEOUT. I’ve previously used0.4.0for ages now and just upgraded tolatest. issue has resolved nowDidn’t look deeper in what you changed but thanks, works for me now.
@vldmarton many thanks for sharing this here. This bit got my curiosity
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?
Only
tickle. They previously said we need to run only one of these endpoints. The docs only speaks oftickle: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
tickleis irrelevant anyway, as the biggest issues come from their servers telling us thatClient login succeedsindicating a successful login, but then theauthenticatestill isfalse, or receiving the503, or the 2FA resulting infailedfor no clear reason. But that’s just my take; point it out if I’m not seeing some application of calling/sso/validate.Yeah… I wouldn’t really have much to comment on this 🤷♂️😔
@Voyz Yes, definitely, the issue has been solved. Thank you!
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.
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’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.
@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 🎉
Hey @Voyz , so they actually got back to me on 26th but I didn’t receive any notification, so I didn’t know about it. Here’s my question (in a nutshell) that I’ve sent to them:
I got this response back:
Right, so I’m assuming that you already do the step 2 based on the logs that appear in container console. How about step 3? When the maintenance schedule is running, do you only call
/tickleendpoint or also/sso/validate?EDIT: 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 🤣
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.
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:And on
0.4.4:I suppose one indication that things aren’t right is that on your machine the
chromium --versionproduced theError: Can't open display:.Great to see you tried this. Let us know what they say.
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:
authenticated:falsereturnsfalsefor 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’d feel that prompting IBKR to fix things would be the right way to go here.
Eventually it worked 🤷♂️
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.