Voyz / ibeam

IBeam is an authentication and maintenance tool used for the Interactive Brokers Client Portal Web API Gateway.
Apache License 2.0
547 stars 111 forks source link

Another IB login page change? #145

Closed jimrobinson closed 1 year ago

jimrobinson commented 1 year ago

Describe the bug I am suspicious that IB has changed their login page again, breaking compatibility with what IBeam is expecting.

The system was working OK on 2023-06-16, and failing on 2023-06-19. I'm seeing a message that makes me think IBeam can no longer recognize / load the login form.

2023-06-20 13:47:39,965|I| No active sessions, logging in...
2023-06-20 13:47:39,965|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
2023-06-20 13:48:03,363|W| Cannot determine the version of IBKR website, assuming version 1
2023-06-20 13:48:23,773|E| Timeout reached when waiting for authentication. The website seems to not be loaded correctly. Consider increasing IBEAM_PAGE_LOAD_TIMEOUT.
Website URL: https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
IBEAM_PAGE_LOAD_TIMEOUT: 15
Exception:
  File "/usr/local/lib/python3.7/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/usr/local/lib/python3.7/threading.py", line 926, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.7/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 80, in _worker
    work_item.run()
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/opt/venv/lib/python3.7/site-packages/apscheduler/executors/base.py", line 125, in run_job
    retval = job.func(*job.args, **job.kwargs)
  File "/srv/ibeam/ibeam/src/gateway_client.py", line 360, in _maintenance
    success, shutdown = self.start_and_authenticate(request_retries=var.REQUEST_RETRIES)
  File "/srv/ibeam/ibeam/src/gateway_client.py", line 332, in start_and_authenticate
    success, shutdown = self.try_authenticating(request_retries=request_retries)
  File "/srv/ibeam/ibeam/src/gateway_client.py", line 256, in try_authenticating
    success, shutdown = self._authenticate()
  File "/srv/ibeam/ibeam/src/gateway_client.py", line 233, in _authenticate
    two_fa_handler=self.two_fa_handler)
  File "/srv/ibeam/ibeam/src/authenticate.py", line 261, in authenticate_gateway
    WebDriverWait(driver, 15).until(user_name_present)
  File "/opt/venv/lib/python3.7/site-packages/selenium/webdriver/support/wait.py", line 95, in until
    raise TimeoutException(message, screen, stacktrace)

To Reproduce I restarted IBeam and the logs indicated the above issue.

I then tried visiting the port 5000 page directly and pulled a login page down, which I filled in an submitted successfully. After that IBeam indicated it was successfully logged in.

Expected behavior I would have expected IBeam to navigate the login page.

Environment IBeam version: v0.4.5 Docker image or standalone: Docker image Python version (standalone users only): OS: Linux

Additional context I notice that the login page now has a large javascript component, I'm unclear on whether or not it had this before:

       <script type="text/javascript">
       ...
            $(document).ready(function() {
                window.IBSSO.XYZ.inject({
                  WRAPPER: '.loginformWrapper',
                  INJECTED_CALLBACK: function(err) {
                      if (err) return;
                      $('.xyz-append-hook').append('<div class="gstat pt-3"></div>');
                      getMaintenaceMsg();

                  },
                  CONSOLE_LOGGING: false,
                  LOGIN_DEBUG: false,
                  LOCALE: 'en-US',
                  IS_WHITE_BRANDED: false,

                  SERVICE: 'AM.LOGIN',

                  POST_FORWARD_PARAMETER: '22',

                  SHOW_LOGIN_TYPE: false,

                  LOGIN_TYPE: '0',

                  SHOW_TEMP_PASSWORD_SENT: false,
                  SHOW_TITLE: true,
                  PAGE_TITLE: 'Login',
                  PASSWORD_RESET_URL: '/credential.recovery/login-help',
                  SHOW_PASSWORD_RESET: true,
                  SHOW_CRED_RECOVERY: true,

                  SHOW_REGISTER_LINK: true,
                  SHOW_FEEDBACK: false
                })

                showCookieConsent();

            });
       ...

When it executes it renders the following page:

ib-login.post-js-hook.html.txt

This page contains a form with input elements that I would think would be matched by the code looking for elements By.NAME "username" and "password" (in version 2 of the login credentials searched for):

...
                <input type="text" class="form-control form-control-lg xyz-username" name="username" placeholder="Username" aria-label="Username" maxlength="64" autocomplete="off" autocorrect="off" autocapitalize="none" spellcheck="false" required="" aria-required="true" value="">
...
                <input type="password" class="form-control form-control-lg xyz-password" name="password" placeholder="Password" aria-label="Password" maxlength="40" autocomplete="off" autocorrect="off" autocapitalize="none" spellcheck="false" required="" aria-required="true">
...

Suggest a Fix I'm not confident to suggest it but I was wondering if it's possible that the JS is not being executed correctly to render the elements that IBeam is looking for.

jimrobinson commented 1 year ago

Hrm, this is confusing... I restarted ibeam w/ IBEAM_ERROR_SCREENSHOTS enabled to see if i could capture more information, and it appears on this go-around it executed the JS and loaded the login form successfully.

2023-06-20 15:22:00,826|I| No active sessions, logging in...
2023-06-20 15:22:00,826|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on
2023-06-20 15:22:08,826|I| Gateway auth webpage loaded
2023-06-20 15:22:08,826|I| Login attempt number 1
2023-06-20 15:22:13,990|I| Submitting the form
2023-06-20 15:22:14,794|I| Webpage displayed "Client login succeeds"
2023-06-20 15:22:16,796|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7f8d76d44fd0> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="fce01cc08bf9c9c2abe19d3e3a98403e")>
2023-06-20 15:22:16,852|I| Authentication process succeeded
2023-06-20 15:22:20,030|I| Gateway running and authenticated.
2023-06-20 15:22:20,035|I| Starting maintenance with interval 60 seconds
2023-06-20 15:23:20,036|I| Maintenance
2023-06-20 15:23:20,163|I| Gateway running and authenticated
2023-06-20 15:24:20,037|I| Maintenance
2023-06-20 15:24:20,166|I| Gateway running and authenticated
2023-06-20 15:25:20,036|I| Maintenance
2023-06-20 15:25:20,168|I| Gateway running and authenticated
Voyz commented 1 year ago

hey @jimrobinson thanks for all the details 👍

Note that the error Timeout reached when waiting for authentication. The website seems to not be loaded correctly. indicates that the page has most likely not loaded at all, as opposed to having loaded an incorrect version. This could indicate some connectivity or server errors at the time.

As for that JavaScript - no idea, but I remember that their page contains a load of JavaScript from when I read it the first time a couple of years ago.

Still, it's hard to tell what's going on if it started working again. Keep the IBEAM_ERROR_SCREENSHOTS on and if the issue persists please report back 🙏

jimrobinson commented 1 year ago

Thanks, will do.

eswark18 commented 1 year ago

2023-06-21 13:52:49,780|I| Gateway started with pid: 13 2023-06-21 13:52:49,858|I| Cannot ping Gateway. Retrying for another 20 seconds 2023-06-21 13:52:51,368|I| Gateway connection established 2023-06-21 13:53:06,395|E| Connection timeout after 15 seconds. Consider increasing timeout by setting IBEAM_REQUEST_TIMEOUT environment variable. Error: The read operation timed out 2023-06-21 13:53:06,395|I| No active sessions, logging in... 2023-06-21 13:53:06,395|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on 2023-06-21 13:53:13,664|I| Gateway auth webpage loaded 2023-06-21 13:53:13,665|I| Login attempt number 1 2023-06-21 13:53:18,810|I| Submitting the form 2023-06-21 13:53:19,557|I| Webpage displayed "Client login succeeds" 2023-06-21 13:53:21,557|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7f2efb40dd10> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="f5ce321eed87afd870c2a20aa3caf3e4")> 2023-06-21 13:53:21,587|I| Authentication process succeeded 2023-06-21 13:53:39,611|E| Connection timeout after 15 seconds. Consider increasing timeout by setting IBEAM_REQUEST_TIMEOUT environment variable. Error: The read operation timed out 2023-06-21 13:53:39,611|I| Attempt number 2 2023-06-21 13:53:54,633|E| Connection timeout after 15 seconds. Consider increasing timeout by setting IBEAM_REQUEST_TIMEOUT environment variable. Error: The read operation timed out 2023-06-21 13:53:54,634|I| Max validate request retries reached after 2 attempts. Consider increasing the retries by setting IBEAM_REQUEST_RETRIES environment variable 2023-06-21 13:53:54,634|E| Gateway running but has no active sessions 2023-06-21 13:53:54,638|I| Starting maintenance with interval 60 seconds 2023-06-21 13:54:54,638|I| Maintenance 2023-06-21 13:55:09,647|E| Connection timeout after 15 seconds. Consider increasing timeout by setting IBEAM_REQUEST_TIMEOUT environment variable. Error: The read operation timed out 2023-06-21 13:55:09,647|I| No active sessions, logging in... 2023-06-21 13:55:09,647|I| Loading auth webpage at https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on 2023-06-21 13:55:30,453|E| Timeout reached when waiting for authentication. The website seems to not be loaded correctly. Consider increasing IBEAM_PAGE_LOAD_TIMEOUT. Website URL: https://localhost:5000/sso/Login?forwardTo=22&RL=1&ip2loc=on IBEAM_PAGE_LOAD_TIMEOUT: 15 Exception: File "/usr/local/lib/python3.11/threading.py", line 995, in _bootstrap self._bootstrap_inner() File "/usr/local/lib/python3.11/threading.py", line 1038, in _bootstrap_inner self.run() File "/usr/local/lib/python3.11/threading.py", line 975, in run self._target(*self._args, self._kwargs) File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 83, in _worker work_item.run() File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, *self.kwargs) File "/opt/venv/lib/python3.11/site-packages/apscheduler/executors/base.py", line 125, in run_job retval = job.func(job.args, job.kwargs) File "/srv/ibeam/src/gateway_client.py", line 360, in _maintenance success, shutdown = self.start_and_authenticate(request_retries=var.REQUEST_RETRIES) File "/srv/ibeam/src/gateway_client.py", line 332, in start_and_authenticate success, shutdown = self.try_authenticating(request_retries=request_retries) File "/srv/ibeam/src/gateway_client.py", line 256, in try_authenticating success, shutdown = self._authenticate() File "/srv/ibeam/src/gateway_client.py", line 228, in _authenticate return authenticate_gateway(driver_path=self.driver_path, File "/srv/ibeam/src/authenticate.py", line 252, in authenticate_gateway driver.get(base_url + var.ROUTE_AUTH) File "/opt/venv/lib/python3.11/site-packages/selenium/webdriver/remote/webdriver.py", line 449, in get self.execute(Command.GET, {"url": url}) 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)

<class 'selenium.common.exceptions.TimeoutException'> Message: timeout: Timed out receiving message from renderer: -0.003 (Session info: headless chrome=113.0.5672.126) Stacktrace:

0 0x5637c1189e43

1 0x5637c0ec1908

2 0x5637c0eacaec

3 0x5637c0eac87b

4 0x5637c0eab234

5 0x5637c0eab850

6 0x5637c0ebd9f3

7 0x5637c0ebe982

8 0x5637c0ecbddf

9 0x5637c0ecfc91

10 0x5637c0eabe27

11 0x5637c0ecbc20

12 0x5637c0f3d55b

13 0x5637c0f25773

14 0x5637c0ef26de

15 0x5637c0ef3a72

16 0x5637c115a7d2

17 0x5637c115cf7b

18 0x5637c115c9f6

19 0x5637c115d6f5

20 0x5637c116347b

21 0x5637c115daa6

22 0x5637c113b074

23 0x5637c1176b75

24 0x5637c1176d1e

25 0x5637c118456f

26 0x7f08857c2ea7 start_thread

2023-06-21 13:55:30,453|I| Cleaning up the resources. Display: <pyvirtualdisplay.display.Display object at 0x7f2efa282510> | Driver: <selenium.webdriver.chrome.webdriver.WebDriver (session="6fb95fb9c2dfc09d5c99d6bbbc87d1fb")> 2023-06-21 13:55:30,483|I| Authentication process failed

This error noticed with the latest version

jimrobinson commented 1 year ago

@eswark18 , I was actually planning on closing out this ticket this morning.

Today, about 30 minutes before the markets opened, I checked that ibeam was properly authenticated and I could make requests of the API, and it was working fine.

When the market opened ibeam reported it was no longer logged in and started spewing the same sorts of errors you indicate in your comment.

This time around I had access to port 5000 (the Java app IB is distributing) and could hit it at the same time as I was observing these errors in the ibeam logs. As far as I can tell from observation, the problem was indeed on the IB side of things. The login page was taking in excess of 30 seconds to load, and wouldn't respond when I tried to submit credentials.

About 06:45 (Pacific) it finally started responding, and I could see that ibeam was able to login.

So I strongly suspect this is some sort of load issue on the IB side of things, as the timing matches pretty well with what happened yesterday (recovery around 06:45 (Pacific)). It's just a personal theory but given my years in software development and operations I am suspicious that they may have rolled out a change on their side that isn't able to handle a load spike around the time of market open.

Voyz commented 1 year ago

Hey @eswark18 thanks for sharing your log. Looking at it, I'd lean towards hypothesising that there were some connectivity issue on your end in this case. You can see that IBeam fails to communicate with the Gateway on number of times:

2023-06-21 13:53:06,395|E| Connection timeout after 15 seconds. Consider increasing timeout by setting IBEAM_REQUEST_TIMEOUT environment variable. Error: The read operation timed out

If this was a Gateway/IBKR issues, we'd see a different type of error. I'm not 100% on this, but this is my intuition at this point. I'd suggest looking into your setup, network, and possibly trying it in a different configuration or on a different machine. If you could share more details about your setup we could help you look into this further.

jimrobinson commented 1 year ago

@Voyz Just FYI, I've opened a ticket with IB asking if they were aware of (and willing to admit to...) any problems. I'm set up now to generate an HAR against browser request to port 5000 if this happens again tomorrow. If I hear back from IB w/ anything useful I'll update this ticket. Otherwise I'll plan to close the ticket if I determine there's not anything to be done from my side.

Voyz commented 1 year ago

@jimrobinson many thanks for sharing these observations.

When the market opened ibeam reported it was no longer logged in and started spewing the same sorts of errors you indicate in your comment.

  1. The Connection timeout after 15 seconds. Consider increasing timeout by setting errors? Could you share your log too if available?

  2. Was it exactly correlated with the market open event? That could be some good clue.

the problem was indeed on the IB side of things

I mean, to be frank, grand majority of problems we encounter here are on IB side. IBeam is just trying to mitigate these problems and find ways around these. Just to underline: the requests go directly to the Gateway/IB, IBeam doesn't intercept or process these in between, just attempts to authenticate automatically.

The login page was taking in excess of 30 seconds to load, and wouldn't respond when I tried to submit credentials.

Yeah, I was seeing this happening a lot recently too. It seems quite random, sometimes it loads, sometimes it doesn't. I'd imagine the servers being overloaded.

So I strongly suspect this is some sort of load issue on the IB side of things

Yeah, there isn't really anything else to point at. Apart from load, I'd attribute it to possible misconfiguration and/or bugs and/or techincal limitations on their side. The best we can do is to submit support tickets to let them know how urgently we require attention in this area.

I've opened a ticket with IB asking if they were aware of (and willing to admit to...) any problems. I'm set up now to generate an HAR against browser request to port 5000 if this happens again tomorrow.

Great stuff. If possible, add a video recording of the issue at hand if you can. I also have a similar ticket open with them, sent HAR files and all, but I hardly get any replies. Hence it's important we do this as a joint effort, in order for their team to understand the breadth of these issues.

Thanks for all your support here! 🙏

jimrobinson commented 1 year ago

Hi @Voyz ,

1. The `Connection timeout after 15 seconds. Consider increasing timeout by setting ` errors? Could you share your log too if available?

2. Was it exactly correlated with the market open event? That could be some good clue.

Yes, 'Connection timeout after 15 seconds' was the first of the errors and it happened at 13:29:35 UTC. Then it struggled for awhile until 13:47:14 UTC. During the problematic period it sometimes loaded the login page successfully but then raised an error that the login credentials were wrong. This was a false error, the credentials are not changing throughout this sequence of login attempts, and it does eventually succeed. I've attached a snippet of the log below, from 13:00 UTC to 13:59 UTC.

ibeam_log__2023-06-21.txt

Yeah, there isn't really anything else to point at. Apart from load, I'd attribute it to possible misconfiguration and/or bugs and/or techincal limitations on their side. The best we can do is to submit support tickets to let them know how urgently we require attention in this area.

I've opened a ticket with IB asking if they were aware of (and willing to admit to...) any problems. I'm set up now to generate an HAR against browser request to port 5000 if this happens again tomorrow.

Great stuff. If possible, add a video recording of the issue at hand if you can. I also have a similar ticket open with them, sent HAR files and all, but I hardly get any replies. Hence it's important we do this as a joint effort, in order for their team to understand the breadth of these issues.

Yeah, I'm not optimistic they'll admit to anything but we'll see. I'm not sure how I'd go about setting up a video recording of the session, but if I can figure it out w/o too much trouble I'll try to make one.

Voyz commented 1 year ago

Yes, 'Connection timeout after 15 seconds' was the first of the errors and it happened at 13:29:35 UTC.

That's really interesting. @eswark18 that could suggest that your errors weren't related to your setup after all like I suspected. I haven't seen this error behaviour before.

This was a false error, the credentials are not changing throughout this sequence of login attempts, and it does eventually succeed

Yeah, the Gateway defaults to generic errors such as 'failed' and 'Invalid username password combination' when in reality these aren't the actual errors. It's safer to treat these as generic 'something went wrong' errors, than to read into the message.

I'm not sure how I'd go about setting up a video recording of the session, but if I can figure it out w/o too much trouble I'll try to make one.

Run IBeam (or the Gateway only) on your local system and then just access https://localhost:5000 from your browser. Then do a screen recording using loom or OBS as you authenticate manually

jimrobinson commented 1 year ago

Hi @Voyz , @eswark18:

IB did reply to my ticket and stated that they have been having problems on their end for the last two days, but that they think the problem has been solved. Here's the reply from them:

Dear Mr. Robinson,

The gateway has been instable for the past 2 days and it was failing to initiate the brokerage session.

We apologize for inconvenience caused. The issues have been resolved now, but please let us know if you will experience similar gateway behavior today.

Kind regards,
Olga Bo
IBKR Client Services