LEAN Fails to Terminate After Interactive Brokers Disconnection

simonsonjack commented 5 years ago

Expected Behavior

If someone opens TWS or IB Gateway, IB should kick LEAN off and terminate the connection. LEAN should stop immediately and not attempt to reconnect until a user intentionally re-deploys their algorithm.

Actual Behavior

There is currently some confusion. LEAN appears to be attempting to reconnect to IB after a user opened TWS rather than immediately terminating.

Reproducing the Problem

Reproducing the issue would be to connect an algorithm to an IB account and have it running, login via TWS or IB Gateway, and then examine the sys logs to see LEAN's response.

Checklist

[x] I have completely filled out this template
[x] I have confirmed that this issue exists on the current master branch
[x] I have confirmed that this is not a duplicate issue by searching issues
[x] I have provided detailed steps to reproduce the issue

StefanoRaggi commented 5 years ago

I believe this issue was fixed recently: https://github.com/QuantConnect/Lean/pull/3228

With master builds after this PR was merged, any user starting TWS with an algorithm running (and also choosing to disconnect the remote session -- the running algorithm), should cause the algorithm to terminate with this runtime error:

A new competing session was started from another location 
and the current session has been terminated.

Before the PR, LEAN would have tried to reconnect, as described in the "Actual Behavior".

Perhaps this issue was reported for an algorithm deployed before the merge?

simonsonjack commented 5 years ago

Possibly, although I don't think so. He mentioned this happening recently and that PR was merged almost three weeks ago. This is a brief snippet of the logs when the errors started occurring if that helps at all

2019-06-07 04:23:00 Brokerage Warning: Market data farm connection is broken:usopt
2019-06-07 04:23:04 Brokerage Warning: Market data farm connection is OK:usopt
2019-06-07 04:32:13 Brokerage Warning: Connectivity between IB and Trader Workstation has been lost.
2019-06-07 04:36:13 Brokerage Warning: Market data farm connection is broken:usopt
2019-06-07 04:36:13 Brokerage Warning: Market data farm connection is broken:usfarm
2019-06-07 04:36:13 Brokerage Warning: Connectivity between IB and Trader Workstation has been restored - data maintained.
2019-06-07 04:36:15 Brokerage Info: System.Net.Sockets.SocketException (0x80004005): Connection refused.   at System.Net.Sockets.TcpClient..ctor (System.String hostname, System.Int32 port) [0x0006d] in <a360a10e096b4659a9142a244ddaea3e>:0 .   at IBApi.EClientSocket.createClientStream (System.String host, System.Int32 port) [0x00001] in <157d4e40593a4bff95e01b0ef064385d>:0 .   at IBApi.EClientSocket.eConnect (System.String host, System.Int32 port, System.Int32 clientId, System.Boolean extraAuth) [0x00034] in <157d4e40593a4bff95e01b0ef064385d>:0 
2019-06-07 04:36:34 Brokerage Info: Market data farm is connecting:usfarm
2019-06-07 04:36:34 Brokerage Warning: The API request has been rate limited. To avoid this message, please reduce the frequency of API calls.
2019-06-07 04:36:35 Brokerage Info: Market data farm is connecting:usopt
2019-06-07 04:36:35 Brokerage Warning: Market data farm connection is OK:usfarm
2019-06-07 04:36:35 Brokerage Warning: The API request has been rate limited. To avoid this message, please reduce the frequency of API calls.
2019-06-07 04:36:35 Brokerage Warning: The API request has been rate limited. To avoid this message, please reduce the frequency of API calls.
2019-06-07 04:36:35 Brokerage Warning: Market data farm connection is OK:usopt
2019-06-07 04:36:36 Brokerage Warning: The API request has been rate limited. To avoid this message, please reduce the frequency of API calls.
2019-06-07 13:31:00 OnTradeBarConsolidated called on 2019-06-07 09:31:00.000335
2019-06-07 15:00:00 OnTradeBarConsolidated called on 2019-06-07 11:00:00.000773
2019-06-07 16:40:00 OnTradeBarConsolidated called on 2019-06-07 12:40:00.078692
2019-06-07 18:20:00 OnTradeBarConsolidated called on 2019-06-07 14:20:00.757348
2019-06-07 20:00:00 OnTradeBarConsolidated called on 2019-06-07 16:00:00.311895
2019-06-07 20:01:02 Brokerage Warning: The API request has been rate limited. To avoid this message, please reduce the frequency of API calls.
2019-06-07 23:05:01 Brokerage Warning: The API request has been rate limited. To avoid this message, please reduce the frequency of API calls.
2019-06-07 23:05:01 Brokerage Warning: The API request has been rate limited. To avoid this message, please reduce the frequency of API calls.
2019-06-08 03:13:06 Brokerage Warning: Connectivity between IB and Trader Workstation has been lost.
2019-06-08 03:13:06 Brokerage Warning: Connectivity between IB and Trader Workstation has been lost.
2019-06-08 04:00:27 Brokerage Info: System.IO.IOException: Unable to read data from the transport connection: Connection reset by peer. ---> System.Net.Sockets.SocketException: Connection reset by peer.   at System.Net.Sockets.Socket.Receive (System.Byte[] buffer, System.Int32 offset, System.Int32 size, System.Net.Sockets.SocketFlags socketFlags) [0x00016] in <a360a10e096b4659a9142a244ddaea3e>:0 .   at System.Net.Sockets.NetworkStream.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 size) [0x0009b] in <a360a10e096b4659a9142a244ddaea3e>:0 .    --- End of inner exception stack trace ---.   at System.Net.Sockets.NetworkStream.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 size) [0x000e2] in <a360a10e096b4659a9142a244ddaea3e>:0 .   at System.IO.BinaryReader.FillBuffer (System.Int32 numBytes) [0x00061] in <b0e1ad7573a24fd5a9f2af9595e677e7>:0 .   at System.IO.BinaryReader.ReadInt32 () [0x00026] in <b0e1ad7573a24fd5a9f2af9595e677e7>:0 .   at IBApi.EClient.ReadInt () [0x0000c] in <157d4e40593a4bff95e01b0ef064385d>:0 .   at IBApi.EReader.readSingleMessage () [0x0000e] in <157d4e40593a4bff95e01b0ef064385d>:0 .   at IBApi.EReader.putMessageToQueue () [0x00002] in <157d4e40593a4bff95e01b0ef064385d>:0 
2019-06-08 04:00:27 Brokerage Warning: Connectivity between Trader Workstation and server is broken. It will be restored automatically.
2019-06-08 04:00:27 Brokerage Warning: Market data farm connection is OK:usfarm
2019-06-08 04:00:27 Brokerage Error: Unexpected, not connected state. Unable to connect to Interactive Brokers. Terminating algorithm.
2019-06-08 04:00:27 Brokerage Error: Can't find EId with tickerId:2824. Origin: Subscribe: OPT SPY USD Smart
2019-06-08 04:00:27 Brokerage Error: Can't find EId with tickerId:3534. Origin: Subscribe: OPT SPY USD Smart

jaredbroad commented 5 years ago

@simonsonjack please deploy a live algorithm and test the behavior in production

simonsonjack commented 5 years ago

Per Jared's request, I ran a test by deploying an algorithm live to IB and then manually logging in to my account via TWS. Error returned

Runtime Error: A new competing session was started from another location and the current session has been terminated. Stack Trace: System.Exception: A new competing session was started from another location and the current session has been terminated.

Looks like IBAutomator successfully detected the competing session and LEAN shut down properly.

StefanoRaggi commented 5 years ago

@simonsonjack I believe this is not an IB connection issue, but an issue with the option chain being refreshed during the IB nightly/weekend reset period.

This error is the result of an attempt to subscribe to an option contract on Saturday at midnight:

2019-06-08 04:00:27 Brokerage Error: Can't find EId with tickerId:2824. Origin: Subscribe: OPT SPY USD Smart

StefanoRaggi commented 5 years ago

@Martin-Molinero This issue should be fixed by #3314, right?

Martin-Molinero commented 5 years ago

Correct, new master behavior is to hold universe selection (for coarse, futures and options) (and in consequence adding or removing subscriptions) if time.Hour >= 23pm or time.Hour <= 5am or its a Saturday. Ref https://github.com/QuantConnect/Lean/pull/3314/files#diff-95f291622834d50427fc1007809439e6R602

simonsonjack commented 5 years ago

@StefanoRaggi Jared mentioned that it could be as simple as the user not having options data or having an open order for an expired contract, so I think we can close this thread as it appears to be a user-issue and definitely not related to IB Automator

hmate9 commented 4 years ago

@simonsonjack I would like to reopen this issue.

It seems this issue is not solved and I have just tested this on a live algorithm.

2019-07-11 13:23:00 : | 2019-07-11T09:23:00.0000410: We have 90 bars
2019-07-11 13:24:00 : | 2019-07-11T09:24:00.0014170: We have 91 bars
2019-07-11 13:24:21 : | Brokerage Warning: Connectivity between IB and Trader Workstation has been lost.
2019-07-11 13:25:00 : | 2019-07-11T09:25:00.0000370: We have 92 bars
2019-07-11 13:26:00 : | 2019-07-11T09:26:00.0000900: We have 92 bars

This is an algo running live, but with QuantConnect Data as it uses a custom universe. I logged in manually via TWS and then you see the Brokerage Warning: Connectivity between IB and Trader Workstation has been lost. being logged.

However, the algorithm carried on running without a connection to IB. The algorithm should have submitted orders at 9:31 but it did nothing. I then stopped and redeployed the exacty same algo and it correctly sent in the orders that it should have (the algorithm sends in a MOC close after market open).

QuantConnect / Lean