gnzsnz / ib-gateway-docker

Docker image with IB Gateway/TWS and IBC
https://github.com/users/gnzsnz/packages/container/package/ib-gateway
MIT License
232 stars 44 forks source link

socat Connection timed out issue #77

Closed peebeejay closed 5 months ago

peebeejay commented 7 months ago

Describe the bug

Once again, thank you for all the fantastic work on this docker image!

I have a container running the ib-gateway-docker image that has been running for a few days. The daily restart occurs at 1AM, and last night, around 1 hour after the restart, a set of errors began to appear, which I can't seem to properly understand. Essentially, what I'd like to figure out is the cause of the issue, and whether the issue is solvable here at the container level, or somewhere deeper in the stack, such as with IBC. Any help would be much appreciated!

Is the issue caused by not waiting for the Forking :::4001 onto 0.0.0.0:4003 > trading mode live line to appear?

Ostensibly, the error message was triggered by a 1-min heartbeat related request that I use for uptime monitoring. The python on the client side that makes this request looks something like this:

from ib_insync import IB
import cronitor

ib_monitor = cronitor.Monitor("ib-monitor")

def connect_ibkr_silent(ib_instance, client_id=1):
    port = getIBPort()

    try:
        ib_instance.connect("127.0.0.1", port, clientId=client_id, timeout=10)
    except Exception as e:
        return

def ping_ib():
    try:
        connect_ibkr_silent(ib_for_ping, client_id=999)
        if ib_for_ping.isConnected():
            logger.trace("Pinging cronitor (ib-monitor)...")
            ib_monitor.ping(env=ENV, name="ibkr")
        ib_for_ping.disconnect()

    except Exception:
        ib_for_ping.disconnect()

The logs from the docker container look something like this:

ib-gateway-1  | 2024-02-08 01:00:06:642 IBC: detected frame entitled: Authenticating...; event=Activated                                                                                                                                                                         
ib-gateway-1  | 2024-02-08 01:00:06:644 IBC: detected frame entitled: Authenticating...; event=Focused                                                                                                                                                                           
ib-gateway-1  | 2024-02-08 01:00:06:644 IBC: detected frame entitled: Authenticating...; event=Opened                                                                                                                                                                            
ib-gateway-1  | LogModuleConfigurator-Init: Log4j Ver2.x found on classpath                                                                                                                                                                                                      
ib-gateway-1  | LogModuleConfigurator-Init: LogModuleConfigurator initialized with Log4j Verd.x                                                                                                                                                                                  
ib-gateway-1  | 2024-02-08 01:00:09:033 IBC: detected frame entitled: Starting application...; event=Lost focus                                                                                                                                                                  
ib-gateway-1  | 2024-02-08 01:00:09:048 IBC: detected dialog entitled: U11****** Trader Workstation Configuration; event=Opened                                                                                                                                                  
ib-gateway-1  | 2024-02-08 01:00:09:048 IBC: detected frame entitled: Starting application...; event=Deactivated                                                                                                                                                                 
ib-gateway-1  | 2024-02-08 01:00:09:048 IBC: Got config dialog from future                                                                                                                                                                                                       
ib-gateway-1  | 2024-02-08 01:00:09:048 IBC: Got config dialog from future                                                                                                                                                                                                       
ib-gateway-1  | 2024-02-08 01:00:09:048 IBC: Got config dialog from future                                                                                                                                                                                                       
ib-gateway-1  | 2024-02-08 01:00:09:048 IBC: detected dialog entitled: U11****** Trader Workstation Configuration; event=Activated                                                                                                                                               
ib-gateway-1  | 2024-02-08 01:00:09:049 IBC: detected dialog entitled: U11****** Trader Workstation Configuration; event=Focused                                                                                                                                                 
ib-gateway-1  | 2024-02-08 01:00:09:050 IBC: detected dialog entitled: U11****** Trader Workstation Configuration; event=Lost focus                                                                                                                                              
ib-gateway-1  | 2024-02-08 01:00:09:050 IBC: detected frame entitled: Starting application...; event=Closed                                                                                                                                                                      
ib-gateway-1  | 2024-02-08 01:00:09:050 IBC: Login has completed                                                                                                                                                                                                                 
ib-gateway-1  | 2024-02-08 01:00:09:051 IBC: detected dialog entitled: U11****** Trader Workstation Configuration; event=Focused                                                                                                                                                 
ib-gateway-1  | 2024-02-08 01:00:09:051 IBC: Setting ReadOnlyApi                                                                                                                                                                                                                 
ib-gateway-1  | 2024-02-08 01:00:09:214 IBC: Read-Only API checkbox is already set to: false                                                                                                                                                                                     
ib-gateway-1  | 2024-02-08 01:00:09:226 IBC: 'Bypass Order Precautions for API Orders' is already selected                                                                                                                                                                       
ib-gateway-1  | 2024-02-08 01:00:09:226 IBC: 'Bypass Bond warning for API Orders' is already selected                                                                                                                                                                            
ib-gateway-1  | 2024-02-08 01:00:09:226 IBC: 'Bypass negative yield to worst confirmation for API Orders' is already selected                                                                                                                                                    
ib-gateway-1  | 2024-02-08 01:00:09:226 IBC: 'Bypass Called Bond warning for API Orders' is already selected                                                                                                                                                                     
ib-gateway-1  | 2024-02-08 01:00:09:226 IBC: 'Bypass "same action pair trade" warning for API orders.' is already selected                                                                                                                                                       
ib-gateway-1  | 2024-02-08 01:00:09:226 IBC: 'Bypass price-based volatility risk warning for API Orders' is already selected                                                                                                                                                     
ib-gateway-1  | 2024-02-08 01:00:09:226 IBC: 'Bypass US Stocks market data in shares warning for API Orders' is already selected                                                                                                                                                 
ib-gateway-1  | 2024-02-08 01:00:09:226 IBC: 'Bypass Redirect Order warning for Stock API Orders' is already selected                                                                                                                                                            
ib-gateway-1  | 2024-02-08 01:00:09:226 IBC: Checkbox 'Bypass No Overfill Protection precaution for destinations where implied natively' not found                                                                                                                               
ib-gateway-1  | 2024-02-08 01:00:09:226 IBC: Setting Auto restart time                                                                                                                                                                                                           
ib-gateway-1  | 2024-02-08 01:00:09:245 IBC: Auto restart time already set to 01:00 AM                                                                                                                                                                                           
ib-gateway-1  | 2024-02-08 01:00:09:262 IBC: Configuration tasks completed                                                                                                                                                                                                       
ib-gateway-1  | 2024-02-08 01:00:09:263 IBC: Click button: OK                                                                                                                                                                                                                    
ib-gateway-1  | 2024-02-08 01:00:09:359 IBC: detected dialog entitled: U11****** Trader Workstation Configuration; event=Lost focus                                                                                                                                              
ib-gateway-1  | 2024-02-08 01:00:09:359 IBC: detected dialog entitled: U11****** Trader Workstation Configuration; event=Deactivated                                                                                                                                             
ib-gateway-1  | 2024-02-08 01:00:09:359 IBC: detected dialog entitled: U11****** Trader Workstation Configuration; event=Closed                                                                                                                                                  
ib-gateway-1  | 2024-02-08 01:00:09:370 IBC: detected dialog entitled: Pending Tasks; event=Closed                                                                                                                                                                               
ib-gateway-1  | 2024/02/08 01:57:50 socat[24203] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 01:58:53 socat[24204] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 01:59:00 socat[24205] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:00:11 socat[24206] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:01:21 socat[24207] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:02:33 socat[24208] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:03:42 socat[24209] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:04:52 socat[24210] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:06:03 socat[24211] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:07:13 socat[24212] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:08:25 socat[24213] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:08:58 socat[24214] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:09:34 socat[24215] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:10:46 socat[24216] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:11:56 socat[24217] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:13:05 socat[24218] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:14:17 socat[24219] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:15:27 socat[24220] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:16:38 socat[24221] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:17:48 socat[24222] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:18:58 socat[24223] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     
ib-gateway-1  | 2024/02/08 02:19:10 socat[24224] E connect(5, AF=2 127.0.0.1:4001, 16): Connection timed out                                                                                                                                                                     

To Reproduce

docker run command: docker compose up

docker-compose.yml

version: "3.4"

name: ib-gateway-prod
services:
  ib-gateway:
    platform: linux/x86_64
    restart: always
    build:
      context: ./stable
      tags:
        - "ghcr.io/gnzsnz/ib-gateway:stable"
    image: ghcr.io/gnzsnz/ib-gateway:stable
    environment:
      TWS_USERID: ${TWS_USERID}
      TWS_PASSWORD: ${TWS_PASSWORD}
      TRADING_MODE: ${TRADING_MODE:-paper}
      TWS_SETTINGS_PATH: ${TWS_SETTINGS_PATH:-}
      READ_ONLY_API: ${READ_ONLY_API:-}
      VNC_SERVER_PASSWORD: ${VNC_SERVER_PASSWORD:-}
      TWOFA_TIMEOUT_ACTION: ${TWOFA_TIMEOUT_ACTION:-exit}
      BYPASS_WARNING: ${BYPASS_WARNING:-}
      AUTO_RESTART_TIME: ${AUTO_RESTART_TIME:-}
      AUTO_LOGOFF_TIME: ${AUTO_LOGOFF_TIME:-}
      SAVE_TWS_SETTINGS: ${SAVE_TWS_SETTINGS:-}
      RELOGIN_AFTER_TWOFA_TIMEOUT: ${RELOGIN_AFTER_TWOFA_TIMEOUT:-no}
      TWOFA_EXIT_INTERVAL: ${TWOFA_EXIT_INTERVAL:-60}
      TIME_ZONE: ${TIME_ZONE:-Etc/UTC}
      TZ: ${TIME_ZONE:-Etc/UTC}
      CUSTOM_CONFIG: ${CUSTOM_CONFIG:-NO}
      JAVA_HEAP_SIZE: ${JAVA_HEAP_SIZE:-}
      SSH_TUNNEL: ${SSH_TUNNEL:-}
      SSH_OPTIONS: ${SSH_OPTIONS:-}
      SSH_ALIVE_INTERVAL: ${SSH_ALIVE_INTERVAL:-}
      SSH_ALIVE_COUNT: ${SSH_ALIVE_COUNT:-}
      SSH_PASSPHRASE: ${SSH_PASSPHRASE:-}
      SSH_REMOTE_PORT: ${SSH_REMOTE_PORT:-}
      SSH_USER_TUNNEL: ${SSH_USER_TUNNEL:-}
      SSH_RESTART: ${SSH_RESTART:-}
      SSH_VNC_PORT: ${SSH_VNC_PORT:-}
    ports:
      - "127.0.0.1:4001:4003"
      # - "127.0.0.1:4002:4004"
      # - "127.0.0.1:5900:5900"

docker compose config

name: ib-gateway-prod
services:
  ib-gateway:
    build:
      context: /home/ethter2/quant/git/trading-infra/cruncher/services/ib-gateway-docker/prod/stable
      dockerfile: Dockerfile
      tags:
        - ghcr.io/gnzsnz/ib-gateway:stable
    environment:
      AUTO_LOGOFF_TIME: ""
      AUTO_RESTART_TIME: 01:00 AM
      BYPASS_WARNING: "yes"
      CUSTOM_CONFIG: "NO"
      JAVA_HEAP_SIZE: "1024"
      READ_ONLY_API: "no"
      RELOGIN_AFTER_TWOFA_TIMEOUT: "yes"
      SAVE_TWS_SETTINGS: ""
      SSH_ALIVE_COUNT: ""
      SSH_ALIVE_INTERVAL: ""
      SSH_OPTIONS: ""
      SSH_PASSPHRASE: ""
      SSH_REMOTE_PORT: ""
      SSH_RESTART: ""
      SSH_TUNNEL: ""
      SSH_USER_TUNNEL: ""
      SSH_VNC_PORT: ""
      TIME_ZONE: America/New_York
      TRADING_MODE: live
      TWOFA_EXIT_INTERVAL: "60"
      TWOFA_TIMEOUT_ACTION: restart
      TWS_PASSWORD: <HIDDEN>
      TWS_SETTINGS_PATH: ""
      TWS_USERID: <HIDDEN>
      TZ: America/New_York
      VNC_SERVER_PASSWORD: ""
    image: ghcr.io/gnzsnz/ib-gateway:stable
    networks:
      default: null
    platform: linux/x86_64
    ports:
      - mode: ingress
        host_ip: 127.0.0.1
        target: 4003
        published: "4001"
        protocol: tcp
    restart: always
networks:
  default:
    name: ib-gateway-prod_default

Expected

I expect these errors to not occur and for the connection to be more stable. Perhaps also expect that the logs say more about this particular issue.

Container logs

See above

Versions

Please complete the following information:

gnzsnz commented 7 months ago

hi,

based on what i can see on the log, it seems that

what could be the cause, well i don't know much details, but i would start looking at

The advantage of reqRealTimeBars is that it behaves more robust when the connection to the IB server farms is interrupted. After the connection is restored, the bars from during the network outage will be backfilled and the live bars will resume.

reqHistoricalData + keepUpToDate will, at the moment of writing, leave the whole API inoperable after a network interruption.
The One Rule:

While some of the request methods are blocking from the perspective of the user, the framework will still keep spinning in the background and handle all messages received from TWS/IBG. It is important to not block the framework from doing its work. If, for example, the user code spends much time in a calculation, or uses time.sleep() with a long delay, the framework will stop spinning, messages accumulate and things may go awry.

The one rule when working with the IB class is therefore that user code may not block for too long.

hope it helps

peebeejay commented 7 months ago

if socat is working, then the issue is on 127.0.0.1:4001 which is the ibgateway port listening on localhost. so ibgateway is not listening. why? i don't know there is nothing on the log to diagnose that. data connection between ibgateway and IBKR seems to be OK. it would be in the logs if it's not.

Hm, from your deductions it seems that some sort of port-related misbehavior is occurring on the part of IB gateway after the nightly restart. I'm going to take a deeper look at this today & see if I can replicate locally during the day.

how are you doing the heartbeat? are you requesting bars periodically?

I've just been using the python code in a literal sense that I posted above lol. In the past, the function called reqCurrentTime, but I felt that for now, I can rely on ib_insync to keep isConnected in sync.

are you using async?

Currently not using async. Restarting my trading system doesn't fix the issue, so from that I infer that it's likely not due to an async blocking issue in ib_insync. 🤔

Ty for the response though, I really appreciate it. I'll report back with any interesting results as they come.

gnzsnz commented 7 months ago

I'm removing the "bug" label, as so far we can't say this is caused by the container code base. if your investigation shows that it is please feel free to add it again.