Connection raises TimeoutError, but IB gateway is running and port is open

[KIC]

I only have one account and a telnet localhost 4002 gives me a shell as I would expect. Sadly I could not find a way to download and try an older version of the gateway. The current version for linux is 981.3c.

API connection failed: TimeoutError()
---------------------------------------------------------------------------
TimeoutError                              Traceback (most recent call last)
<ipython-input-10-13991e279071> in <module>
      1 con = ib.IB()
----> 2 con.connect('localhost', 4002, clientId=1)

~/.local/lib/python3.8/site-packages/ib_insync/ib.py in connect(self, host, port, clientId, timeout, readonly, account)
    269             account: Main account to receive updates for.
    270         """
--> 271         return self._run(self.connectAsync(
    272             host, port, clientId, timeout, readonly, account))
    273 

~/.local/lib/python3.8/site-packages/ib_insync/ib.py in _run(self, *awaitables)
    308 
    309     def _run(self, *awaitables: Awaitable):
--> 310         return util.run(*awaitables, timeout=self.RequestTimeout)
    311 
    312     def waitOnUpdate(self, timeout: float = 0) -> bool:

~/.local/lib/python3.8/site-packages/ib_insync/util.py in run(timeout, *awaitables)
    320         globalErrorEvent.connect(onError)
    321         try:
--> 322             result = loop.run_until_complete(task)
    323         except asyncio.CancelledError as e:
    324             raise globalErrorEvent.value() or e

~/.local/lib/python3.8/site-packages/nest_asyncio.py in run_until_complete(self, future)
     68                 raise RuntimeError(
     69                     'Event loop stopped before Future completed.')
---> 70             return f.result()
     71 
     72     def _run_once(self):

/usr/lib/python3.8/asyncio/futures.py in result(self)
    176         self.__log_traceback = False
    177         if self._exception is not None:
--> 178             raise self._exception
    179         return self._result
    180 

/usr/lib/python3.8/asyncio/tasks.py in __step(***failed resolving arguments***)
    278                 # We use the `send` method directly, because coroutines
    279                 # don't have `__iter__` and `__next__` methods.
--> 280                 result = coro.send(None)
    281             else:
    282                 result = coro.throw(exc)

~/.local/lib/python3.8/site-packages/ib_insync/ib.py in connectAsync(self, host, port, clientId, timeout, readonly, account)
   1624         try:
   1625             # establish API connection
-> 1626             await self.client.connectAsync(host, port, clientId, timeout)
   1627 
   1628             # autobind manual orders

~/.local/lib/python3.8/site-packages/ib_insync/client.py in connectAsync(self, host, port, clientId, timeout)
    216                 b' ' + self.connectOptions if self.connectOptions else b''))
    217             self.conn.sendMsg(msg)
--> 218             await asyncio.wait_for(self.apiStart, timeout)
    219             self._logger.info('API connection ready')
    220         except Exception as e:

/usr/lib/python3.8/asyncio/tasks.py in wait_for(fut, timeout, loop)
    499             # See https://bugs.python.org/issue32751
    500             await _cancel_and_wait(fut, loop=loop)
--> 501             raise exceptions.TimeoutError()
    502     finally:
    503         timeout_handle.cancel()

[somefreestring]

it is not Mac alone it comes up in windows as well

venv\Lib\site-packages\ib_insync\client.py", line 218, in connectAsync await asyncio.wait_for(self.apiStart, timeout) File "c:\program files\python39\lib\asyncio\tasks.py", line 491, in wait_for raise exceptions.TimeoutError() from exc asyncio.exceptions.TimeoutError

have you got around the timeout error? https://github.com/erdewit/ib_insync/issues/388#issuecomment-888524499

[erdewit]

--> 218 await asyncio.wait_for(self.apiStart, timeout)

The timeout happens while waiting for the apiStart event. It looks like either the validReqId or the list of accounts is not being sent by TWS/gateway. Which one can be seen by logging the network traffic, for example by setting

util.logToConsole('DEBUG')

[erdewit]

Mark, you are not logging at debug level. If someone can run the following snippet:

from ib_insync import *
util.logToConsole('DEBUG')
ib = IB()
ib.connect()

and copy-paste the result that'be great.

[erdewit]

Mark, I deleted 6 posts of yours with long stack traces that only conflate the issue here. If someone can run the snippet above and post the network traffic then some progress can be made.

[lianyidao]

@erdewit The TimeoutError exception raises when ib_insync connects to ibgw 985.1g, everything is ok when working with ibgw 981.3c.

I did a tcpdump for the code snippet above, after the first message(b'API\x00\x00\x00\x09v142\x2e\x2e152') is sent, only an ACK with no payload is received from ibgw, then the TimeoutError exception is raised after timeout.

[Girish400]

[erdewit]

Thanks guys. The tcpdump tells us that there's nothing coming from the gateway; The whole API handshake is just left hanging. I have installed the 985.1h release but still can't reproduce the issue. There's a new popup about "market data in shares" that has to be clicked away first, so make sure to do that before connecting.

It would be instructive to know if the ibapi client can still connect.

[Girish400]

Hi Ewald,

In API settings "Send Market data in lots for US stocks for dual-mode API Clients" is checked. Same program runs in Windows but not on Mac. Please find the screen prints below

[stopdesign]

Is there a socket connection in CLOSE_WAIT state during the issue?

I noticed that both TWS (on Mac) and IBGateway (in Docker) would set the socket to CLOSE_WAIT state when the connection was opened and wasn't closed with the disconnect() method. It happens even if I use python socket connect to test if the port is open. Even if I close it explicitly.

import socket
with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as s:
    s.connect_ex(('127.0.0.1', 4001))
    s.close()

...and it is locked:

# lsof -i -P -n
COMMAND NODE  NAME
socat    TCP  *:4001 (LISTEN)
java     TCP  *:7462 (LISTEN)
java     TCP  127.0.0.1:4002->127.0.0.1:41652 (CLOSE_WAIT)              <<<<<<    THIS ONE
java     TCP  172.25.0.2:55792->64.190.197.40:4001 (ESTABLISHED)
java     TCP  172.25.0.2:37634->64.190.197.40:4000 (ESTABLISHED)
java     TCP  *:4002 (LISTEN)
java     TCP  172.25.0.2:37636->64.190.197.40:4000 (ESTABLISHED)
x11vnc   TCP  *:5900 (LISTEN)
x11vnc   TCP  *:5900 (LISTEN)
x11vnc   TCP  172.25.0.2:5900->172.25.0.1:51436 (ESTABLISHED)

After that I have to restart IBGateway / TWS or change the port in settings.

[swiftzhen]

If the message limitation has been checked regarding to the following original documentation: https://interactivebrokers.github.io/tws-api/introduction.html#limitations

[lianyidao]

Upgrade to ibgateway-latest-standalone-linux-x64-985.1k solved the Timeout problem for me.

[skozlovf]

Hi All. I have similar issue. Updating to 981.3c and 985.1k doesn't help. It always hangs at some point.

My env: Debian stretch 9.11 LXDE, in docker (AWS ECS). python 3.7.5 ib-insync 0.9.66

I tested in simmulation mode with both TWS/IBGW.

My test (simplified):

    import ib_insync as ibns
    from ib_insync import util

    util.logToConsole('DEBUG')

    account = 'DU671616'
    ib = ibns.IB()

    print('connect ...')
    ib.connect('127.0.0.1', 7777, 1, 30)

    print('portfolio(): ')
    ib.client.reqAccountUpdates(False, account)
    ib.reqAccountUpdates(account)

    print('balance(): ')
    ib.accountValues(account)

Stripped debug logs (ibgateway test):

connect ...                                                                                                                                                                                                                          [753/4991]
2021-08-24 03:08:23,386 ib_insync.client INFO Connecting to 127.0.0.1:4002 with clientId 1...
2021-08-24 03:08:23,387 ib_insync.client INFO Connected
2021-08-24 03:08:23,396 ib_insync.client DEBUG <<< 152,20210824 03:08:22 PST
2021-08-24 03:08:23,396 ib_insync.client DEBUG >>> 71,2,1,
2021-08-24 03:08:23,396 ib_insync.client INFO Logged on to server version 152
2021-08-24 03:08:23,398 ib_insync.client DEBUG <<< 15,1,DF671611,DU671612,DU671613,DU671614,DU671615,DU671616,
2021-08-24 03:08:23,442 ib_insync.client DEBUG <<< 9,1,1
2021-08-24 03:08:23,442 ib_insync.client DEBUG <<< 4,2,-1,2158,Sec-def data farm connection is OK:secdefnj
2021-08-24 03:08:23,442 ib_insync.wrapper INFO Warning 2158, reqId -1: Sec-def data farm connection is OK:secdefnj
2021-08-24 03:08:23,442 ib_insync.client INFO API connection ready
2021-08-24 03:08:23,443 ib_insync.client DEBUG >>> 61,1
2021-08-24 03:08:23,443 ib_insync.client DEBUG >>> 99,0
2021-08-24 03:08:23,444 ib_insync.client DEBUG >>> 76,1,1,DF671611,,0
2021-08-24 03:08:23,445 ib_insync.client DEBUG >>> 76,1,2,DU671612,,0
2021-08-24 03:08:23,445 ib_insync.client DEBUG >>> 76,1,3,DU671613,,0
2021-08-24 03:08:23,445 ib_insync.client DEBUG >>> 76,1,4,DU671614,,0
2021-08-24 03:08:23,446 ib_insync.client DEBUG >>> 76,1,5,DU671615,,0
2021-08-24 03:08:23,446 ib_insync.client DEBUG >>> 76,1,6,DU671616,,0
2021-08-24 03:08:23,447 ib_insync.client DEBUG <<< 62,1
2021-08-24 03:08:23,449 ib_insync.client DEBUG <<< 102
2021-08-24 03:08:23,554 ib_insync.client DEBUG <<< 73,1,1,DF671611,,AccountCode,DF671611,
.....
2021-08-24 03:08:23,558 ib_insync.client DEBUG <<< 8,1,22:19
2021-08-24 03:08:23,561 ib_insync.client DEBUG <<< 73,1,1,DF671611,,AccruedCash,0.00,USD
12021-08-24 03:08:23,619 ib_insync.client DEBUG <<< 8,1,22:19                                                                                                                                                                         [633/4991]
2021-08-24 03:08:23,619 ib_insync.client DEBUG <<< 73,1,1,DF671611,,AccountOrGroup,DF671611,BASE
...
2021-08-24 03:08:23,639 ib_insync.client DEBUG <<< 74,1,1
2021-08-24 03:08:23,640 ib_insync.client DEBUG <<< 73,1,2,DU671612,,AccountCode,DU671612,
...
2021-08-24 03:08:23,645 ib_insync.client DEBUG <<< 8,1,22:19                                                                                                                                                                         [567/4991]
2021-08-24 03:08:23,645 ib_insync.client DEBUG <<< 73,1,2,DU671612,,AccruedCash,-176.64,USD
...
2021-08-24 03:08:23,678 ib_insync.client DEBUG <<< 74,1,2
2021-08-24 03:08:23,678 ib_insync.client DEBUG <<< 73,1,3,DU671613,,AccountCode,DU671613,
...
2021-08-24 03:08:53,474 ib_insync.ib ERROR account updates for DU671616 request timed out                                                                                                                                             [13/4540]
2021-08-24 03:08:53,474 ib_insync.client DEBUG >>> 7,3,7,0,,,,,,
2021-08-24 03:08:53,475 ib_insync.client DEBUG <<< 55,1,7
2021-08-24 03:08:53,475 ib_insync.ib INFO Synchronization complete
portfolio(): 
2021-08-24 03:08:53,475 ib_insync.client DEBUG >>> 6,2,0,DU671616
2021-08-24 03:08:53,475 ib_insync.client DEBUG >>> 6,2,1,DU671616
2021-08-24 03:09:00,470 ib_insync.client DEBUG <<< 73,1,1,DF671611,,NetLiquidation,881.70,USD
2021-08-24 03:09:00,470 ib_insync.client DEBUG <<< 8,1,03:09
2021-08-24 03:09:02,942 ib_insync.client DEBUG <<< 73,1,2,DU671612,,NetLiquidation,1011024.11,USD
2021-08-24 03:09:02,942 ib_insync.client DEBUG <<< 8,1,03:09
2021-08-24 03:09:02,942 ib_insync.client DEBUG <<< 73,1,3,DU671613,,NetLiquidation,879322.50,USD
2021-08-24 03:09:02,942 ib_insync.client DEBUG <<< 8,1,03:09
2021-08-24 03:09:02,942 ib_insync.client DEBUG <<< 73,1,5,DU671615,,NetLiquidation,1499806.52,USD
2021-08-24 03:09:02,943 ib_insync.client DEBUG <<< 8,1,03:09
2021-08-24 03:09:02,943 ib_insync.client DEBUG <<< 6,2,NetLiquidation,1037240.34,USD,DU671616
2021-08-24 03:09:02,943 ib_insync.client DEBUG <<< 8,1,03:09
2021-08-24 03:09:02,943 ib_insync.client DEBUG <<< 8,1,03:09
2021-08-24 03:09:02,943 ib_insync.client DEBUG <<< 73,1,6,DU671616,,NetLiquidation,1037240.34,USD
2021-08-24 03:09:02,944 ib_insync.client DEBUG <<< 8,1,03:09
2021-08-24 03:11:23,818 ib_insync.client DEBUG <<< 73,1,4,DU671614,,NetLiquidation,1943552.34,USD
2021-08-24 03:11:23,818 ib_insync.client DEBUG <<< 8,1,03:11
2021-08-24 03:12:00,471 ib_insync.client DEBUG <<< 73,1,1,DF671611,,NetLiquidation,881.70,USD
2021-08-24 03:12:00,471 ib_insync.client DEBUG <<< 8,1,03:12
2021-08-24 03:12:02,943 ib_insync.client DEBUG <<< 73,1,2,DU671612,,NetLiquidation,1011024.11,USD
2021-08-24 03:12:02,944 ib_insync.client DEBUG <<< 8,1,03:12
2021-08-24 03:12:02,944 ib_insync.client DEBUG <<< 73,1,3,DU671613,,NetLiquidation,879322.50,USD
2021-08-24 03:12:02,945 ib_insync.client DEBUG <<< 8,1,03:12
2021-08-24 03:12:02,945 ib_insync.client DEBUG <<< 73,1,5,DU671615,,NetLiquidation,1499806.52,USD
2021-08-24 03:12:02,945 ib_insync.client DEBUG <<< 8,1,03:12
2021-08-24 03:12:02,945 ib_insync.client DEBUG <<< 8,1,03:12
2021-08-24 03:12:02,945 ib_insync.client DEBUG <<< 8,1,03:12
2021-08-24 03:12:02,946 ib_insync.client DEBUG <<< 73,1,6,DU671616,,NetLiquidation,1037240.34,USD
2021-08-24 03:12:02,946 ib_insync.client DEBUG <<< 8,1,03:12
.... hang

Note timestamps. Sometimes connection may be fast, sometimes it takes minutes.

[erdewit]

@skozlovf:

2021-08-24 03:08:53,474 ib_insync.ib ERROR account updates for DU671616 request timed out

This case is different from the others. The connection succeeds, but looks like there is a problem with one of the accounts where no account updates are being send. The other accounts seem fine.

[skozlovf]

@erdewit It works fine with 978.2q.

I tested with different account DU671615. It connects without the error and even finishes. But update runs super slow (few minutes). With 978.2q it runs fast and for any account.

Also I started getting this error in the test and in production code

Connectivity between IB and Trader Workstation has been restored - data maintained. All data farms are connected: usfarm.nj; cashfarm; usfarm; euhmds; fundfarm; ushmds; secdefil.

Any clues? Thanks.

[KIC]

still happening with the most recent gateway, you can just run the docker and the smoketest.py from my repo: https://github.com/KIC/ibgateway

python smoketest.py
2021-08-25 13:25:13,596 ib_insync.client INFO Connecting to 127.0.0.1:4002 with clientId 1...
2021-08-25 13:25:13,596 ib_insync.client INFO Connected
2021-08-25 13:25:13,600 ib_insync.client INFO Disconnected.
2021-08-25 13:25:17,601 ib_insync.client INFO Disconnecting
2021-08-25 13:25:17,601 ib_insync.client ERROR API connection failed: TimeoutError()
Traceback (most recent call last):
  File "smoketest.py", line 4, in <module>
    ib.connect('127.0.0.1', 4002)
  File "/home/kic/.local/lib/python3.8/site-packages/ib_insync/ib.py", line 271, in connect
    return self._run(self.connectAsync(
  File "/home/kic/.local/lib/python3.8/site-packages/ib_insync/ib.py", line 310, in _run
    return util.run(*awaitables, timeout=self.RequestTimeout)
  File "/home/kic/.local/lib/python3.8/site-packages/ib_insync/util.py", line 322, in run
    result = loop.run_until_complete(task)
  File "/usr/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/home/kic/.local/lib/python3.8/site-packages/ib_insync/ib.py", line 1626, in connectAsync
    await self.client.connectAsync(host, port, clientId, timeout)
  File "/home/kic/.local/lib/python3.8/site-packages/ib_insync/client.py", line 218, in connectAsync
    await asyncio.wait_for(self.apiStart, timeout)
  File "/usr/lib/python3.8/asyncio/tasks.py", line 501, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

[erdewit]

@KIC:

you can just run the docker

If I do that then even telnet localhost 4002 cannot connect. So it looks like there's some problem with the docker image.

[KIC]

works for me

@erdewit did you start the container like described in the readme?

[erdewit]

did you start the container like described in the readme?

Yes I did, and the gateway is running fine in the container (as viewed with VNC). But the connection to port 4002 immediately gets closed by the remote peer:

$ telnet localhost 4002
Trying ::1...
Connected to localhost.
Escape character is '^]'.
Connection closed by foreign host.

[dmoklaf]

This bug may have had the same root cause as #355 , i.e., a "bleeding edge" version of the IB Gateway that had a buggy protocol subtlety.

-> @KIC does it still occur with the latest IB Gateway update?

[KIC]

Sadly, yes with the most recent Gateway downloaded today:

2021-11-11 12:23:45,776 ib_insync.client INFO Connecting to 127.0.0.1:4002 with clientId 1...
2021-11-11 12:23:45,776 ib_insync.client INFO Connected
2021-11-11 12:23:45,777 ib_insync.client INFO Disconnected.
2021-11-11 12:23:49,779 ib_insync.client INFO Disconnecting
2021-11-11 12:23:49,779 ib_insync.client ERROR API connection failed: TimeoutError()
Traceback (most recent call last):
  File "smoketest.py", line 4, in <module>
    ib.connect('127.0.0.1', 4002)
  File "/home/kic/.local/lib/python3.8/site-packages/ib_insync/ib.py", line 271, in connect
    return self._run(self.connectAsync(
  File "/home/kic/.local/lib/python3.8/site-packages/ib_insync/ib.py", line 310, in _run
    return util.run(*awaitables, timeout=self.RequestTimeout)
  File "/home/kic/.local/lib/python3.8/site-packages/ib_insync/util.py", line 332, in run
    result = loop.run_until_complete(task)
  File "/usr/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/home/kic/.local/lib/python3.8/site-packages/ib_insync/ib.py", line 1628, in connectAsync
    await self.client.connectAsync(host, port, clientId, timeout)
  File "/home/kic/.local/lib/python3.8/site-packages/ib_insync/client.py", line 218, in connectAsync
    await asyncio.wait_for(self.apiStart, timeout)
  File "/usr/lib/python3.8/asyncio/tasks.py", line 501, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

While the gateway is connected properly to the paper account

[erdewit]

I experienced this error myself, and the linux command sudo ss -tulpn showed the API port being hogged by a an old TWS process. Apparently TWS does not always exit cleanly. Killing the process fixes the problem.

[Mikkel84]

I have the same issue, probably also related to a running process. Is there a common process name that I can blame for, because I cannot spot the one that is causing the error.

[erdewit]

It's a Java process.

[zdytch]

Any idea how to automate a workaround? I'm able to see those FD's stuck in (CLOSE_WAIT) statuses. But how to keep watching constantly and release them without killing the whole pid?

% lsof -i :4001
COMMAND     PID   USER   FD   TYPE             DEVICE SIZE/OFF NODE NAME
JavaAppli 84119 alexey   52u  IPv6 0x90ab05d7775bfacf      0t0  TCP 192.168.88.247:58392->ndc1.ibllc.com:newoak (ESTABLISHED)
JavaAppli 84119 alexey   71u  IPv6 0x90ab05d7680704af      0t0  TCP *:newoak (LISTEN)
JavaAppli 84119 alexey   72u  IPv6 0x90ab05d768070acf      0t0  TCP localhost:newoak->localhost:60199 (CLOSE_WAIT)
JavaAppli 84119 alexey   74u  IPv6 0x90ab05d6fed0896f      0t0  TCP localhost:newoak->localhost:59403 (CLOSE_WAIT)

[andreyohiienko]

@erdewit @stopdesign @zdytch

is there any way to prevent or handle the CLOSE_WAIT issue? Thanks

[faroukBakari]

You need to manually set timeout this way : ib.connect('127.0.0.1', 7497, clientId=1, timeout=1000)