Problem with ib.reqCurrentTime() with latest TWS version?

[mdelvaux]

It seems this is an issue in TWS itself, but I provide a description here anyhow as it could also be an interaction effect between TWS and ib_insync.

Since updating TWS to Build 10.16.1f, Jun 2, 2022 4:45:09 PM, my standard loop code breaks. The loop is typically a forever loop with a waitOnUpdate(0.1) to more or less match the rate of ticker update. The code still works running with the gateway.

After digging, it seems the problem is in reqCurrentTime(), everything else seems to work fine, and specifically when calling reqCurrentTime() faster than once per second. I have no good idea why this would happen. Here is the smallest reproducible code that triggers the behavior

delay = 1.1 for i in range(10): print(f"Loop {i}, delay {delay:.1f}") print(f"{ib.reqCurrentTime()}") ib.waitOnUpdate(delay) delay = max(0.1, delay - 0.1)

Running this code result in this output, with the code never returning from reqCurrentTime()

Loop 0, delay 1.1 2022-06-06 05:09:25+00:00 Loop 1, delay 1.0 2022-06-06 05:09:26+00:00 Loop 2, delay 0.9 2022-06-06 05:09:27+00:00 Loop 3, delay 0.8

When that happens in a normal loop, log message linked to event handler still happens, for example a function called at bar updates still work.

[mdelvaux]

I installed the latest gateway, also shown as 10.16.1f, and it fails. The log window and the API window show the following, that is not conclusive but it seems the 4th response message is not sent at all, so it seems to be an issue on the IB side.

Log

2022-06-06 19:25:11.359 [MB] INFO [JTS-EServerSocket-115] - [103:163:163:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:25:12.469 [MB] INFO [JTS-EServerSocket-115] - [103:163:163:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:25:13.471 [MB] INFO [JTS-EServerSocket-115] - [103:163:163:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:25:14.383 [MB] INFO [JTS-EServerSocket-115] - [103:163:163:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:25:31.191 [MB] INFO [JTS-CCPDispatcherS4-51] - Setting time offset to -191 diff 33

Client

19:25:11:135 -> ---49-1-1654568711- 19:25:12:245 <- 49-1- 19:25:12:245 -> ---49-1-1654568712- 19:25:13:247 <- 49-1- 19:25:13:247 -> ---49-1-1654568713- 19:25:14:159 <- 49-1- 19:26:10:513 -> --- 8-1-19:26-

[mdelvaux]

Here is the same test but against 981.3o

Log

2022-06-06 19:34:26.322 [XW] INFO [JTS-EServerSocket-162] - [103:157:157:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:34:27.426 [XW] INFO [JTS-EServerSocket-162] - [103:157:157:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:34:28.432 [XW] INFO [JTS-EServerSocket-162] - [103:157:157:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:34:29.338 [XW] INFO [JTS-EServerSocket-162] - [103:157:157:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:34:30.025 [XW] INFO [JTS-TransferPing-ushmds-140] - Send ping for transfer socket:ushmds at 1654569270025 2022-06-06 19:34:30.147 [XW] INFO [JTS-EServerSocket-162] - [103:157:157:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:34:30.254 [XW] INFO [JTS-TransferPing-usfarm-144] - Send ping for transfer socket:usfarm at 1654569270254 2022-06-06 19:34:30.853 [XW] INFO [JTS-EServerSocket-162] - [103:157:157:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:34:31.461 [XW] INFO [JTS-EServerSocket-162] - [103:157:157:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:34:31.975 [XW] INFO [JTS-EServerSocket-162] - [103:157:157:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:34:32.384 [XW] INFO [JTS-EServerSocket-162] - [103:157:157:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:34:32.696 [XW] INFO [JTS-EServerSocket-162] - [103:157:157:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 202

Client

9:34:25:888 <- 49-1- 19:34:25:888 -> ---49-1-1654569265- 19:34:26:991 <- 49-1- 19:34:26:991 -> ---49-1-1654569266- 19:34:27:997 <- 49-1- 19:34:27:997 -> ---49-1-1654569267- 19:34:28:903 <- 49-1- 19:34:28:904 -> ---49-1-1654569268- 19:34:29:712 <- 49-1- 19:34:29:712 -> ---49-1-1654569269- 19:34:30:418 <- 49-1- 19:34:30:418 -> ---49-1-1654569270- 19:34:31:026 <- 49-1- 19:34:31:026 -> ---49-1-1654569271- 19:34:31:540 <- 49-1- 19:34:31:540 -> ---49-1-1654569271- 19:34:31:949 <- 49-1- 19:34:31:949 -> ---49-1-1654569271- 19:34:32:261 <- 49-1- 19:34:32:261 -> ---49-1-1654569272-

[mdelvaux]

I also wrote an equivalent test using the IB supplied python API and the test does not hang, the corresponding run looks like this and is possible clue for the problem. There are no responses for some of the requests, apparently the IB version of the API caches answers or does some other optimization. I would assume there is no answer if the time in second would be the same?

Log

2022-06-06 19:40:24.460 [HO] INFO [JTS-EServerSocket-85] - [4896:167:167:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:40:25.473 [HO] INFO [JTS-EServerSocket-85] - [4896:167:167:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:40:26.388 [HO] INFO [JTS-EServerSocket-85] - [4896:167:167:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:40:27.195 [HO] INFO [JTS-EServerSocket-85] - [4896:167:167:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:40:27.896 [HO] INFO [JTS-EServerSocket-85] - [4896:167:167:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:40:28.504 [HO] INFO [JTS-EServerSocket-85] - [4896:167:167:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:40:29.017 [HO] INFO [JTS-EServerSocket-85] - [4896:167:167:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:40:29.421 [HO] INFO [JTS-EServerSocket-85] - [4896:167:167:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message. 2022-06-06 19:40:29.732 [HO] INFO [JTS-EServerSocket-85] - [4896:167:167:1:0:0:0:INFO] Handling incoming ReqCurrentTime(49) message.

Client

19:40:23:592 <- 49-1- 19:40:23:593 -> ---49-1-1654569623- 19:40:24:605 <- 49-1- 19:40:24:605 -> ---49-1-1654569624- 19:40:25:520 <- 49-1- 19:40:26:327 <- 49-1- 19:40:26:327 -> ---49-1-1654569626- 19:40:27:028 <- 49-1- 19:40:27:637 <- 49-1- 19:40:27:637 -> ---49-1-1654569627- 19:40:28:149 <- 49-1- 19:40:28:553 <- 49-1- 19:40:28:864 <- 49-1- 19:40:28:864 -> ---49-1-1654569628-

Test code loop, the handler for time simply copy the response into an object variable

def currentTime(self, time):
    self.current_time = time 

        delay = 1.1
        for i in range(10):
            print("Asking for time")
            app.reqCurrentTime()
            time.sleep(delay)
            print(app.current_time)
            delay -= 0.1

[fritol]

from the Docu:

* For harvesting tick data, an imperative code style with a
--
225 | ``waitOnUpdate`` loop should not be used anymore!

Why dont u try the callback construction like here look for ib.pendingTickersEvent += onPendingTickers

[mdelvaux]

This code does not harvest ticks, it just trade, and the snippet also fails if you replace waitOnUpdate() by simply sleep()

[fritol]

ib.pendingTickersEvent += onPendingTickers

works for trading on every tick

[fritol]

also try ib.sleep() its a async version

[mdelvaux]

I used ib.sleep(). Fritol, I don't want to sound too rude, but what you are trying to do here, the problem is linked to ib.reqCurrentTime(), the example code uses waitOnUpdate() but zero reference to tick harvesting. I am assuming you want to help, but I am also forced to assume you did not try to reproduce the issue and may not have analyzed the trace.

The message trace shows a difference of behavior between two instances of TWS that result in breaking ib.reqCurrentTime(). The use of ib.waitOnUpdate or ib.sleep were only there to show when that occurs, when you make more than one reqCurrentTime() call in less than 1 second. The code will also fail (just immediately at the first iteration) if you simply remove any delay from the loop.

I have tried to debug the IB own python API to see what happens in that code base, but I don't yet understand how the code does not hang. Unfortunately, the IB python code uses theads, no asyncio, and that makes debugging more difficult.

[mdelvaux]

Thinking about it, maybe there is no issue in the current IB python code simply because it is not blocking and the caching is provided by my method itself. If I force the cached value to 0, then indeed the time remains zero when update messages are not sent, i.e. with the code below, you get alternate values of 0 and the correct time

Asking for time 1654820890 Asking for time 0 Asking for time 1654820891 Asking for time 0 Asking for time 1654820892 Asking for time 0 Asking for time 1654820893 Asking for time 0 Asking for time 1654820894 Asking for time 0

          delay = 0.5
            for i in range(10):
                print("Asking for time")
                app.current_time = 0
                app.reqCurrentTime()
                time.sleep(delay)
                print(app.current_time)

So there is no special handling in the API itself, and just a difference in the TWS behavior. In turn TWS chokes because it is not blocking and the await never completes.

[mdelvaux]

That means that this issue is tough to solve in the ib_insync framework, except by having a timeout on the await of reqCurrentTimeAsync() plus possibly a caching of the current time.

[mdelvaux]

This is certainly a kludge, but the following code avoids the issue. It makes a direct call to util.run so that it can use a different timeout value. If finishes with the normal call in case something goes wrong before. It has hardcoded values for the loop count and the timeout at this time, with not much optimization. The test code that normally fails now work, and may block for a while, I will attempt an alternate solution that caches IB time instead and returns that value after a timeout

` def reqCurrentTime(self) -> datetime.datetime: """ Request TWS current time.

    This method is blocking.
    """
    # workaround to avoid TWS behavior starting with version 10.16.1f, TWS does not return an answer when
    # reqCurrentTime is called in the same second as a previous call
    for i in range(100):
        try:
            return util.run(self.reqCurrentTimeAsync(), timeout=0.015)
        except:
            pass
    return self._run(self.reqCurrentTimeAsync())`

[mdelvaux]

A better approach caches the last value returned into self.ib_time, then the code looks like below. The advantage is that reqCurrentTime() blocks only for the timeout delay itself, while the previous approach can block for a full second

    def reqCurrentTime(self) -> datetime.datetime:
        """
        Request TWS current time.

        This method is blocking.
        """
        # workaround to avoid TWS behavior starting with version 10.16.1f, TWS does not return an answer when
        # reqCurrentTime is called in the same second as a previous call
        try:
            self.ib_time = util.run(self.reqCurrentTimeAsync(), timeout=0.1)
        except:
            pass
        return self.ib_time

[erdewit]

A global timeout for all blocking requests can be set with IB.RequestTimeout. By default it will wait indefinitely for a response from IB, and if no response is sent at all then that is a problem.

Note that there is nothing special about the time received from reqCurrentTime. It's just a local NTP-synced clock with a crude 1 second resolution. Imho it's better to not rely on it and use the local system time instead (also keeping it NTP-synced). The less reliance on IB the better.