ib.connect Timeout Error on apiStart (Error: Cannot find market rule for conid XXXXXXXXX at exchange)

vocsong commented 2 hours ago

Recently I'm encountering some weird connectivity errors that I've never seen before in past 2-3yrs running my bot. I highly suspect its TWS side issue but I can't really figure out.

Some background:

my bot runs many 0dte spx trades during regular trading hours
I had several friends running my bot all running fine

Some added tests I did to give more context:

I tried to run on my friends PC (his home internet), the issue is exactly the same
I tried using a different username in my IBKR account, it worked fine
Next day i tried back the original username it worked fine again
End of day, 4pm after my bot did a usual auto restart the exact same issue occur again
once it occur, i will not be able to connect to tws with this username again (probably until the 1-2 days later)

At this point i already kinda figure out its some corrupted data somehow on my username when connecting. So I did some own investigating and try to narrow the code to replicate the issue in jupytor notebook:

from ib_async import *
util.startLoop()  # uncomment this line when in a notebook

ib = IB()
ib.connect('127.0.0.1', 7496, clientId=1, fetchFields=StartupFetchNONE, raiseSyncErrors=True )

Here's the errors:

API connection failed: TimeoutError()
---------------------------------------------------------------------------
CancelledError                            Traceback (most recent call last)
File c:\Users\vocs\anaconda3\envs\vocsmbot\Lib\asyncio\tasks.py:500, in wait_for(fut, timeout)
    [499](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:499) try:
--> [500](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:500)     return fut.result()
    [501](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:501) except exceptions.CancelledError as exc:

File c:\Users\vocs\anaconda3\envs\vocsmbot\Lib\asyncio\futures.py:198, in Future.result(self)
    [197](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/futures.py:197)     exc = self._make_cancelled_error()
--> [198](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/futures.py:198)     raise exc
    [199](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/futures.py:199) if self._state != _FINISHED:

File c:\Users\vocs\anaconda3\envs\vocsmbot\Lib\asyncio\tasks.py:279, in Task.__step(***failed resolving arguments***)
    [278](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:278)     else:
--> [279](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:279)         result = coro.throw(exc)
    [280](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:280) except StopIteration as exc:

File c:\Users\vocs\anaconda3\envs\vocsmbot\Lib\asyncio\tasks.py:694, in _wrap_awaitable(awaitable)
    [689](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:689) """Helper for asyncio.ensure_future().
    [690](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:690) 
    [691](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:691) Wraps awaitable (an object with __await__) into a coroutine
    [692](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:692) that will later be wrapped in a Task by ensure_future().
    [693](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:693) """
--> [694](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:694) return (yield from awaitable.__await__())
...
--> [502](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:502)             raise exceptions.TimeoutError() from exc
    [503](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:503) finally:
    [504](file:///C:/Users/vocs/anaconda3/envs/vocsmbot/Lib/asyncio/tasks.py:504)     timeout_handle.cancel()

TimeoutError: 
Output is truncated. View as a [scrollable element](command:cellOutput.enableScrolling?2ff5a916-c6ae-4908-9754-c98f6d63779d) or open in a [text editor](command:workbench.action.openLargeOutput?2ff5a916-c6ae-4908-9754-c98f6d63779d). Adjust cell output [settings](command:workbench.action.openSettings?%5B%22%40tag%3AnotebookOutputLayout%22%5D)...

The above error doesnt help much its just timeout error. I further dug into the ib_insync/ib_async code and see the issue happening here in client.py > connectAsync():

await asyncio.wait_for(ib.client.apiStart, timeout)

I even contacted the IBKR technical support but they're not in anyway helping, giving me random excuses like ib_insync not compatible and their TWS API had recent changelogs which are totally not true.

So i retrieved the TWS log in diagnostic detailed logging, this chunk always happen whenever i do a connect:

2024-10-18 22:23:51.293 [AF] INFO  [JTS-EMsgPacer-279] - [333:176:176:1:0:0:0:INFO] The accountCode is ignored for single account customers
2024-10-18 22:23:51.293 [AF] INFO  [JTS-EMsgPacer-279] - [333:176:176:1:0:0:0:DET] Finished validating message:
2024-10-18 22:23:51.293 [AF] INFO  [JTS-EMsgPacer-279] - [333:176:176:1:0:0:0:DET] Started processing message:
2024-10-18 22:23:51.293 [AF] INFO  [JTS-EMsgPacer-279] - [333:176:176:1:0:0:0:INFO] Requesting trade reports.
2024-10-18 22:23:51.293 [AF] INFO  [JTS-EMsgPacer-279] - Error: Cannot find market rule for conid 732396124 at exchange: 
2024-10-18 22:23:51.293 [AF] INFO  [JTS-EMsgPacer-279] - Error: Dummy ec created has no market rule: conid=732396124
2024-10-18 22:23:51.293 [AF] INFO  [JTS-EMsgPacer-279] - Error: Cannot find market rule for conid 730443310 at exchange: 
2024-10-18 22:23:51.293 [AF] INFO  [JTS-EMsgPacer-279] - Error: Dummy ec created has no market rule: conid=730443310
2024-10-18 22:23:51.293 [AF] INFO  [JTS-EMsgPacer-279] - Error: Cannot find market rule for conid 730443582 at exchange: 
...
...
_(this error dummy ec thing happened few hundred lines)_
...
...
2024-10-18 22:23:51.297 [AF] INFO  [JTS-EMsgPacer-279] - Error: Dummy ec created has no market rule: conid=728048921
2024-10-18 22:23:51.297 [AF] INFO  [JTS-EMsgPacer-279] - Error: Cannot find market rule for conid 731154420 at exchange: 
2024-10-18 22:23:51.297 [AF] INFO  [JTS-EMsgPacer-279] - Error: Dummy ec created has no market rule: conid=731154420
2024-10-18 22:23:51.297 [AF] INFO  [JTS-EMsgPacer-279] - Error: Cannot find market rule for conid 731154420 at exchange: 
2024-10-18 22:23:51.297 [AF] INFO  [JTS-EMsgPacer-279] - Error: Dummy ec created has no market rule: conid=731154420
2024-10-18 22:23:51.297 [AF] INFO  [JTS-EMsgPacer-279] - [333:176:176:1:0:0:0:DET] Finished processing message:
2024-10-18 22:23:55.307 [AF] INFO  [JTS-EServerSocket-275] - [333:176:176:1:0:0:0:ERR] Socket connection for client{333} has closed. Reason: Connection terminated
2024-10-18 22:23:55.307 [AF] INFO  [JTS-EServerSocket-275] - [333:176:176:1:0:0:0:INFO] Stopped processing incoming messages for client{333}.
2024-10-18 22:23:55.307 [AF] INFO  [JTS-EServerSocket-275] - [333:176:176:1:0:0:0:INFO] Close call made for client{333} socket connection.
2024-10-18 22:23:55.307 [AF] INFO  [JTS-EServerSocketNotifier-276] - Terminating async queue thread
2024-10-18 22:23:55.307 [AF] INFO  [JTS-EServerSocket-275] - Cleaning up [serverId: 333]...
2024-10-18 22:23:55.307 [AF] INFO  [AWT-EventQueue-0] - MDConnectionsModel: Updated [127.0.0.1:55397 CLIENT CLOSING 333]
2024-10-18 22:23:55.307 [AF] INFO  [JTS-EServerSocket-275] - Cleaning up [serverId: 333]...
2024-10-18 22:23:55.307 [AF] INFO  [JTS-EServerSocket-275] - Cleaning up [serverId: 333]...
2024-10-18 22:23:55.307 [AF] INFO  [JTS-EServerSocket-275] - [ApiAccountAdditionMgr] Cleaning up [serverId=333]...
2024-10-18 22:23:55.307 [AF] INFO  [JTS-EServerSocket-275] - [333:176:176:1:0:0:0:DET] closePrim called.  Stopping all mkt data and HMDS requests for client{333}.
2024-10-18 22:23:55.308 [AF] INFO  [JTS-EServerSocket-275] - ArEServer: Removing 1673815889 with id 333
2024-10-18 22:23:55.308 [AF] INFO  [JTS-EServerSocket-275] - ============ EServerSocket messages stats ============
2024-10-18 22:23:55.308 [AF] INFO  [JTS-EServerSocket-275] - Number of socket messages pushed to updates queue: 90
2024-10-18 22:23:55.308 [AF] INFO  [JTS-EServerSocket-275] - Number of socket messages sent directly: 2654
2024-10-18 22:23:55.308 [AF] INFO  [JTS-EServerSocket-275] - =======================================================
2024-10-18 22:23:55.308 [AF] INFO  [JTS-EServerSocket-275] - [333:176:176:1:0:0:0:INFO] Closed API client{333} session.
2024-10-18 22:23:55.308 [AF] INFO  [JTS-EServerSocket-275] - There are no API orders being processed.
2024-10-18 22:23:55.308 [AF] INFO  [JTS-EWriter14-277] - [333:176:176:1:0:0:0:INFO] Client{333} already closing or closed.
2024-10-18 22:23:55.308 [AF] INFO  [JTS-EServerSocket-275] - SecDefRequestTimeOut: There are no timed out SecDef requests.
2024-10-18 22:23:55.308 [AF] INFO  [JTS-EWriter14-277] - [333:176:176:1:0:0:0:SYS] Writer thread terminated for socket client{333}.
2024-10-18 22:23:55.308 [AF] INFO  [JTS-EServerSocket-275] - UnhandledOrderPresetRequest: There are no unprocessed order preset requests.
2024-10-18 22:23:55.308 [AF] INFO  [JTS-EServerSocket-275] - [333:176:176:1:0:0:0:SYS] Ending conversation with client{333} at 127.0.0.1
2024-10-18 22:24:00.308 [AF] INFO  [AWT-EventQueue-0] - MDConnectionsModel: Removed [127.0.0.1:55397 CLIENT CLOSING 333]

From what I have so far (above) it seems like something went missing in my account somehow and causing subsequent connect to timeout.

my current workaround if this ever happens is to keep switching the username every other day.. subscribing to marketdata on both username.. which is not the most ideal..

I'm just kinda documenting it here to see if anyone also encounter anything similar.. Or anyone have any idea what else can I try resolve this or even anyone who understand whats going on could help explain and advise anything.. or is there something i can do on ib_async side to prevent triggering the dummy error..

any help would be deeply appreciated. thanks.

vocsong commented 2 hours ago

Some other related TWS logs:

2024-10-18 21:12:54.373 [QY] INFO  [JTS-CCPDispatcherS2-41] - Error: no preferred EC for conid 730443243 no sec defs returned forSecDef  reqId=PreferredReqByConid237
2024-10-18 21:12:54.373 [QY] INFO  [JTS-Async-35] - CM IB PORT Uxxxxxxx./1/147565047: Getting unknown EC instance for conid 730443243...
2024-10-18 21:12:54.373 [QY] WARN  [JTS-Async-35] - Requesting unknown Ec for conid 730443243
2024-10-18 21:12:54.373 [QY] ERROR [AWT-EventQueue-0] - Instrumented AsyncScheduler action stats in OLT min: 0, max: 0, avg: 0 size: 0
2024-10-18 21:12:54.373 [QY] ERROR [JTS-Async-35] -  Creating unknown contract for conid 730443243
2024-10-18 21:12:54.373 [QY] ERROR [JTS-Async-35] -  Requesting unknown DefContent for conid  730443243
2024-10-18 21:12:54.374 [QY] INFO  [JTS-CCPDispatcherS2-41] - Error: no preferred EC for conid 730443310 no sec defs returned forSecDef  reqId=PreferredReqByConid238
2024-10-18 21:12:54.374 [QY] INFO  [JTS-Async-35] - CM IB PORT Uxxxxxxx./1/147565047: Getting unknown EC instance for conid 730443310...
2024-10-18 21:12:54.374 [QY] WARN  [JTS-Async-35] - Requesting unknown Ec for conid 730443310
2024-10-18 21:12:54.374 [QY] ERROR [JTS-Async-35] -  Creating unknown contract for conid 730443310
2024-10-18 21:12:54.374 [QY] ERROR [JTS-Async-35] -  Requesting unknown DefContent for conid  730443310
2024-10-18 21:12:54.375 [QY] INFO  [JTS-CCPDispatcherS2-41] - Error: no preferred EC for conid 728290422 no sec defs returned forSecDef  reqId=PreferredReqByConid240
2024-10-18 21:12:54.375 [QY] INFO  [JTS-Async-35] - CM IB PORT Uxxxxxxx./1/147565047: Getting unknown EC instance for conid 728290422...
2024-10-18 21:12:54.375 [QY] WARN  [JTS-Async-35] - Requesting unknown Ec for conid 728290422
2024-10-18 21:12:54.375 [QY] ERROR [JTS-Async-35] -  Creating unknown contract for conid 728290422
2024-10-18 21:12:54.375 [QY] ERROR [JTS-Async-35] -  Requesting unknown DefContent for conid  728290422

2024-10-18 21:12:54.373 [QY] ERROR [JTS-Async-35] -  Creating unknown contract for conid 730443243
2024-10-18 21:12:54.373 [QY] ERROR [JTS-Async-35] -  Requesting unknown DefContent for conid  730443243
2024-10-18 21:12:54.374 [QY] INFO  [JTS-CCPDispatcherS2-41] - Error: no preferred EC for conid 730443310 no sec defs returned forSecDef  reqId=PreferredReqByConid238
2024-10-18 21:12:54.374 [QY] INFO  [JTS-Async-35] - CM IB PORT Uxxxxxxx./1/147565047: Getting unknown EC instance for conid 730443310...
2024-10-18 21:12:54.374 [QY] WARN  [JTS-Async-35] - Requesting unknown Ec for conid 730443310
2024-10-18 21:12:54.374 [QY] ERROR [JTS-Async-35] -  Creating unknown contract for conid 730443310
2024-10-18 21:12:54.374 [QY] ERROR [JTS-Async-35] -  Requesting unknown DefContent for conid  730443310
2024-10-18 21:12:54.375 [QY] INFO  [JTS-CCPDispatcherS2-41] - Error: no preferred EC for conid 728290422 no sec defs returned forSecDef  reqId=PreferredReqByConid240
2024-10-18 21:12:54.375 [QY] INFO  [JTS-Async-35] - CM IB PORT Uxxxxxxx./1/147565047: Getting unknown EC instance for conid 728290422...
2024-10-18 21:12:54.375 [QY] WARN  [JTS-Async-35] - Requesting unknown Ec for conid 728290422
2024-10-18 21:12:54.375 [QY] ERROR [JTS-Async-35] -  Creating unknown contract for conid 728290422
2024-10-18 21:12:54.375 [QY] ERROR [JTS-Async-35] -  Requesting unknown DefContent for conid  728290422
2024-10-18 21:12:54.376 [QY] INFO  [JTS-CCPDispatcherS2-41] - Error: no preferred EC for conid 730443341 no sec defs returned forSecDef  reqId=PreferredReqByConid239

these happened in huge chunks, i only copy a snippet..

mattsta commented 1 hour ago

That does sound odd.

Generally, "no security definition found" is what IBKR says after a contract id has expired and you just can't look it up anymore.

If the logs are showing error messages of Error: Cannot find market rule for conid then it looks more like an IBKR data problem somewhere. Maybe also log the full contract object too so we can see which ones are failing the lookup.

You can also try running an updated gateway version and also configure it with at least 4096 MB RAM under Settings: https://investors.interactivebrokers.com/en/index.php?f=16454 — it's technically just a headless TWS, but TWS has never worked great for me anyway.

vocsong commented 1 hour ago

Thanks for the quick response. I did some more testing. StartupFetchNONE connected while StartupFetchALL hits the same issue I saw this fetching was merged since June, can i understand what's the potential implication of not fetching?

vocsong commented 1 hour ago

abit more isolation.. i only got the issue when i fetch executions

ib.connect('127.0.0.1', 7496, clientId=777, fetchFields=StartupFetch.EXECUTIONS, raiseSyncErrors=True )

ConnectionError: ['executions request timed out']

mattsta commented 43 minutes ago

i only got the issue when i fetch executions

oh, I see what you're saying.

If it works with NONE, then it must mean somehow your IBKR historical data can't be loaded (expired contracts again?) — but the original problem was also using NONE above too?

There are bugs in TWS/Gateway where sometimes if it gets bad connection attempts or data loading attempts, the entire gateway just stops responding until a full exit/restart (but, if you restart and the next connect attempt generates another bad session, it would continue breaking i guess).

Yes, the fetchFields is an advanced feature and if you don't need it you can leave it undefined. The purpose is to just speed up startup time if you don't want the connect call to load all account data on startup (fetching executions is usually slow and can be delayed until later if run manually).

So one good usage is requesting "load ALL data but not EXECUTIONS":

    fetchFields=ib_async.StartupFetchALL & ~ib_async.StartupFetch.EXECUTIONS,

If you wanted to figure out which fields are breaking for you, you could run through different combinations... StartupFetchALL is just the union of all possible account data on startup:

StartupFetchALL = 
    StartupFetch.POSITIONS    
    | StartupFetch.ORDERS_OPEN                         
    | StartupFetch.ORDERS_COMPLETE
    | StartupFetch.ACCOUNT_UPDATES                        
    | StartupFetch.SUB_ACCOUNT_UPDATES            
    | StartupFetch.EXECUTIONS

The logic for how all those fields are read is here: https://github.com/ib-api-reloaded/ib_async/blob/38cf54a66a4daefbd3fd1d7476381f0d178a8198/ib_async/ib.py#L2030-L2070 — it shows which APIs get called for each data request, but you can also run each of those API data fetches yourself for more debugging too (if only 1 of the 6 is failing or the order required isn't working for some reason).

ib-api-reloaded / ib_async

ib.connect Timeout Error on apiStart (Error: Cannot find market rule for conid XXXXXXXXX at exchange) #82