Possible Ubuntu change preventing automatic log on to IB Gateway with IBC?

[timnilson]

I am running IB Gateway 1025 on Ubuntu with latest version of IBC. Since the most recent security update restart of the ubuntu server, IBC can no longer fill in the username/password details into the IB Gateway window. Nothing on the IBC side has changed. Not seeing any issues in the IBC log. It just stops after recognizing that the state is 'not logged in'. This used to work fine for a many weeks. Anyone experienced something similar?

[rlktradewright]

You've given me nothing to go on, so please reply with your IBC logfile attached (don't quote it inline).

[timnilson]

Here is the log while IB Gateway is in the state of waiting for log in credentials. IBC is running.

ibc-log.txt

Thank you for looking at this!

[rlktradewright]

The short answer: you need to delete this file:

/home/ibdash/Jts/jedlhheopbnfkmneadhdelnnnbbhpbafhcpbgmal/autorestart

Then it should start properly!

Let me try to explain what I think is happening here.

That autorestart file is generated by TWS/Gateway just before the program exits during auto-restart. It contains cryptographically encrypted and sealed user credentials. When the new instance starts, it reads the contents of this file, and uses those credentials to re-establish a session to the IB severs without user (or IBC) involvement, And then it deletes the autorestart file. This process typically takes a couple of seconds. If the autorestart file contains invalid information, TWS/Gateway just displays the login form with empty username and password, as in your screenshot, and waits for user input. I'm not sure what makes it think the file is invalid: possibly the information has an expiry date, or perhaps the file haas been tampered with or perhaps this is the first login on a Sunday so Gateway won't do an auto-restart.

Now, during a normal startup (ie not an auto-restart), when IBC detects the login dialog displayed in this way, it fills in the username and password and clicks the Log In button automatically. But if it has detected the presence of an autorestart file, IBC assumes that the auto-restart sequence described above will happen. So although the login dialog is still displayed, IBC ignores it becausse it expects TWS/Gateway to deal with it using the autorestart file.

So what seems to be the case here is that an autorestart file does exist, IBC thinks it's an auto-restart situation, so it ignores the login dialog, but Gateway doesn't like the contents of the auto-restart file and wants to do a normal user login.

The question is, how did it get into this situation? It's actually quite difficult to deliberately engineer this state, because normally the auto-restart file only exists for literally a few seconds. So I think you must have killed the Gateway (perhaps using Ctrl-C) just after it shut down during auto-restart, and just beofore it started the new instance (or just before the new instance managed to user the autorestart file).

The fact that your logfile contains this line:

IBC returned exit status 143

lends credence to this suggestion, since exit status 143 is caused by SIGTERM. That particular case, of course, wasn't the original cause, which happened some time (days?) earlier - I can't tell because for some reason you didn't give me the whole logfile.

So, my overall advice is don't try to kill Gateway during the auto-restart sequence. In fact, it's best never to just kill it. The best way to shut it down tidily is to send a STOP command to IBC's command server: you configure this via settings in config.ini. To send the command do something like this:

(echo "STOP"; sleep 1; echo "QUIT" ) | telnet 127.0.0.1 7462

I might consider enhancing IBC so that if it's in an auto-restart situation and the login dialog is displayed and login doesn't complete within some timeout period, then IBC will try to initiate the login itself. I haven't done this before now, because the situation just doesn't arise if the auto-restart is properly set up and allowed to do its thing without any interference: at least, that's what I thought but perhaps I'm wrong!...

[timnilson]

Richard -- Thank you so much for your review of my issue and your super detailed response. You're amazing!! I deleted the file you mentioned (which was empty, by the way) and the problem is now solved!! I also enabled the command port (which was 0) by setting it to 7462 and added the stop command you provided into the stop.sh file inside the opt/ibc directory (that stop.sh file was empty). Again, thank you very much for your help resolving this issue!!! All the best!

[grantrosse]

I'm having a similar issue. I'm running this in a docker container on ubuntu and every time it restarts I get this issue:

For context, this is how I'm running the container so I can persist settings: sudo docker run -d -v /ibc/ccgpgldepbhgmoncipijhphmkiaclafiofagjeaj:/root/Jts/ccgpgldepbhgmoncipijhphmkiaclafiofagjeaj:rw --restart unless-stopped -p 8080:8080 -p 5900:5900 -p 80:80 -p 7497:7497 tws

ibc-3.18.0_TWS-1025_Monday.txt

[rlktradewright]

Interesting. This is a rather different case from the one above. The lofgile shows that the restart succeeds nicely at 20:00:34:228, but then at 2023-11-14 00:38:38:050 things start to go wrong: TWS displays a "Connecting to server..." message, followed by a "Re-login is required" dialog. IBC clicks the Re-Login button, but it doesn't help, and it effectvely goes into a loop of TWS redisplaying the "Re-login is required" dialog, and IBC clicking the Re-Login button to no avail.

By the way, the log shows a big gap between 00:43:38:551 and 06:58:25:838 where apparently nothing is logged. I suspect that's because you've removed endless repeating messages. That's fine, but please folks if you edit a logfile in any way please annotate your changes so I know what's been removed and why. In this case it coiuld be that TWS really didn't log anything for six hours, and that would be worth knowing!

Anyway, there's not enough information in the log to know exactly what TWS was wanting, but I suspect it wanted to do a full logon with the user's credentials re-entered (probably due to some problem in the IB servers).

In order to clarify this, and assuming as you say that this is repeatable, can you please run it again with these settings in config.ini:

LogStructureScope=known
LogStructureWhen=open

This will log structure information for every TWS window that IBC recognises, and it will make the logfile huge so if you're able to be there around the time this starts happening, stop it as soon as you can!

Alternatively if you can just get a screenshot showing the 'Relogin is required' dialog, that would probably be enough but it might be impossible to catch as it's only displayed for less than 100ms before IBC handles it and it closes.

[grantrosse]

Thanks for your response, on your comments. I didn't remove anything from the logfile.

Yes, you're right, it does do a successful restart and then it's like it tries to login again? I will rerun with those settings in the config.ini once my account is unlocked.

Here's another error that was up at the time (you can see this one is nested behind the other one in my first screenshot):

One data point I was thinking about: I had autorestart set in the application and in the IBC config.ini so I wonder if that was the issue?

[rlktradewright]

Ok, baffling that nothing was logged for so long after apparently failing to log in. But life is full of mysteries...

But your second screenshot indicates that you don't have things set up properly overall. Clearly you are running another program that uses port 7497 (perhaps that started at 00:38:38 when the problems began).

So, you need to track down where this other program is and prevent it starting. There is nothing that IBC can do to help with this.

Maybe you should consider using ExistingSessionDetectedAction=manual in your config.ini: this will prevent another instance starting with the same login.

Regarding your question about the auto-restart time being set both in TWS and in config.ini, that won't matter: the TWS setting will be changed to whatever's in config.ini, and next time you start you'll get the 'Auto restart time already set to 08:00 PM' message that you can see in your logfile.

Similarly with the other such messages in the logfile: there's no point in using any of these configuration settings in config.ini, because you have a persistent volume that TWS stores its settings in between sessions: you're just setting the same value as it's already got every time.

By the way, it looks like you have a spurious setting

i=

in your config.ini. It appears at the end of the list of settings in the log file. It won't do any harm, but I just thought I'd point it out.

[grantrosse]

Clearly you are running another program that uses port 7497 (perhaps that started at 00:38:38 when the problems began).

I don't have anything else running, do you have any other guesses at what could cause TWS to lose connection and require a login?: 2023-11-14 00:38:38:050 IBC: detected frame entitled: Connecting to server...; event=Opened 2023-11-14 00:43:38:298 IBC: detected dialog entitled: Re-login is required; event=Opened

[rlktradewright]

I am not guessing. There is absolutely no doubt that another instance of TWS (or Gateway) is running with the same API port setting. After working with TWS/Gateway for more than 20 years and developing IBC over the same period, I recognise the signs.

I tried running another instance of TWS with my paper trading login alongside my normal instance and it produced exactly that dialogue about port 7497 being already in use, together with the red lines in the market data grid. It wasn't quite the same in some details, but it might be for example that the other instance is using another login to the same paper account (in which case it must use a different API port) or perhaps is trying to login to the live account.

So, I can't possibly tell what the exact circumstances are, but it's definitely up to you to work out what's going on here.

[grantrosse]

^I started fresh with a new EC2 to eliminate the possibility of something else running and I'm still having this issue every night. Based on the last couple logs it looks like it begins with a server disconnect around 1230: "Connecting to server....." and then it can't recover. However TWS is open in this state: ibc-3.18.0_TWS-1026_Tuesday.txt

Any ideas what I can do to resolve? It does restart successfully once.

[rlktradewright]

Ok I think I've tracked down your problem.

The issue is caused because you're doing everything under the root user. I not sure how you've managed to get TWS to work at all with this setup, unless you've changed some directory permissions: if so, you haven't done enough, because the IBC low-level script ibcstart.sh needs write access to the jts/1026 folder: it has to rename IB's tws script, and this doesn't appear to be happening. If this script is not renamed, then the TWS instance that's closing down during a restart creates a new instance of TWS that is not running under IBC. But the IBC script also creates a new instance of TWS that is running under IBC. Hence the two instances of TWS - yes, there really are two, and they interfere with each other in the various ways that you've experienced. If the IBC script has managed to rename the tws script, then the instance that's closing down fails to create a new instance and just exits, but the IBC script creates a new one and everything is fine.

So please, it really helps to just follow the simple installation instructions, that just work and save everyone a lot of time. Don't run under root. This is nearly always bad practice on Linux, and there's absolutely no need for it.

[grantrosse]

I don't think this is it because IBC does successfully restart and login without also launching another TWS. I can verify that by connecting to the docker container. Every night around 1230 this happens:

It goes lost focus, deactivate, connecting to server...:

2023-11-28 00:31:27:405 IBC: detected frame entitled: DU7744365 Interactive Brokers (Simulated Trading); event=Lost focus 2023-11-28 00:31:27:407 IBC: detected frame entitled: DU7744365 Interactive Brokers (Simulated Trading); event=Deactivated 2023-11-28 00:31:27:408 IBC: detected frame entitled: Connecting to server...; event=Activated 2023-11-28 00:31:27:412 IBC: detected frame entitled: Connecting to server...; event=Focused 2023-11-28 00:31:27:412 IBC: detected frame entitled: Connecting to server...; event=Opened 2023-11-28 00:32:59:573 IBC: detected frame entitled: Attempt 7: Authenticating...; event=Lost focus 2023-11-28 00:32:59:574 IBC: detected frame entitled: Attempt 7: Authenticating...; event=Deactivated 2023-11-28 00:32:59:575 IBC: detected dialog entitled: Re-login is required; event=Activated 2023-11-28 00:32:59:576 IBC: detected dialog entitled: Re-login is required; event=Focused 2023-11-28 00:32:59:577 IBC: detected dialog entitled: Re-login is required; event=Opened 2023-11-28 00:32:59:577 IBC: Re-login to session 2023-11-28 00:32:59:577 IBC: Click button: Re-login 2023-11-28 00:32:59:665 IBC: detected dialog entitled: Re-login is required; event=Lost focus 2023-11-28 00:32:59:665 IBC: detected dialog entitled: Re-login is required; event=Deactivated 2023-11-28 00:32:59:665 IBC: detected frame entitled: Attempt 7: Authenticating...; event=Activated 2023-11-28 00:32:59:665 IBC: detected frame entitled: Attempt 7: Authenticating...; event=Focused 2023-11-28 00:32:59:666 IBC: detected dialog entitled: Re-login is required; event=Closed 2023-11-28 00:32:59:745 IBC: detected frame entitled: ; event=Lost focus 2023-11-28 00:32:59:746 IBC: detected frame entitled: ; event=Deactivated 2023-11-28 00:32:59:828 IBC: detected dialog entitled: DU7744365 IBKR Trader Workstation (Simulated Trading); event=Activated 2023-11-28 00:32:59:829 IBC: detected dialog entitled: DU7744365 IBKR Trader Workstation (Simulated Trading); event=Focused 2023-11-28 00:32:59:829 IBC: detected dialog entitled: Login failed; event=Opened 2023-11-28 00:32:59:830 IBC: Login failed 2023-11-28 00:32:59:838 IBC: detected dialog entitled: DU7744365 IBKR Trader Workstation (Simulated Trading); event=Lost focus 2023-11-28 00:32:59:839 IBC: detected dialog entitled: DU7744365 IBKR Trader Workstation (Simulated Trading); event=Deactivated 2023-11-28 00:32:59:840 IBC: detected dialog entitled: Login failed; event=Activated 2023-11-28 00:32:59:840 IBC: detected dialog entitled: Login failed; event=Focused

[rlktradewright]

Your extract from the logfile doesn't prove anything.

Let me spell out what happens if the tws script (Linux) or tws.exe (WIndows) has not been renamed.

1. When the auto-restart time arrives, TWS instance A (which is running under the IBC start script) creates the autorestart file containing the credentials for the new instance to continue the session.
2. TWS instance A invokes the IBKR start script or icon to start another instance (instance B) and then exits. Note that because instance B is not created by the IBC script, IBC has no knowledge of it at all.
3. The IBC script now checks for the existence of the autorestart file, and because it does exist it knows it's in an auto-restart situation. It therefore also starts another instance (instance C), making sure the autorestart file is passed to it..
4. So now we have two instances of TWS running, both having picked up the autorestart file. They occupy exactly the same area of the screen and look identical, so you wouldn't notice without looking closely.
5. One of these instances will succeed in re-establishing the session, and the other one will fail.

CASE 1 - instance C gets the new session

6. If instance C succeeds in re-establishing the session, then IBC will treat it as an auto-restart (ie ignoring the login dialog because TWS iself deals with that) and you will see a normal auto-restart, as you've observed.
7. Meanwhile instance B will be denied auto restart: in these circumstances, TWS displays the normal login dialog with empty fields, and because it's not running under IBC it will just sit there until something makes it do something different.
8. Eventually instance C reaches its next auto-restart time, and the autorestart will succeed, as shown in the logfile.
9. When it gets to midnight:30, things get a bit fuzzy because I've never tried to engineer this situation. But it may be that the IBKR servers get upset about having one logged-in instance and one untouched instance (that's been sitting there for more tha a day), and decides to get instance C to re-authenticate by displaying the 'Re-login is required' dialog (and maybe get instance B to terminate).
10. IBC does recognise the 'Re-login is required' dialog but in rather different circumstances, and all it ever does is click the 'Re-login' button, but clearly that's not adequate here. I'd need to collect more detailed diagnostics to find out what's going on.

CASE 2- instance B gets the new session

11. If instance B succeeds in re-establishing the session at the first auto-restart, then instance C will display the normal login dialog with empty fields. Without working through the code, I'm not sure what will then happen. I don't think IBC will fill in the username and password and try to login, because it thinks it's in an auto-restart situation. Then eventually the thing will timeout, and I think IBC will be restarted (instance D) and this time it will not be in an auto-restart situation because the autorestart file no longer exists (having been deleted by instance B).
12. So now we get into the 'Existing session detected' scenario, but ti doesn't look like this is happning as I haven't noticed it in your logfiles.

Ok. That's enough of this. As you can see, it's all quite complex. The only way I'd be able to penetrate deeper into this is to set things up the same way you have, and i have neither the time nor the inclination to do so, since this is a non-standard setup.

So the bottom line is PLEASE, just set it up the way it's intended to work and it will run perfectly. If you won't do that, then I don't see why I should waste any more of my time trying to dig you out of the hole you're in.