Closed josephchenhk closed 9 months ago
It could be related to the daily restart, please share the output of docker compose config
. you will want to remove sensitive information like user and pass.
Personally I'm running a container with AUTO_RESTART_TIME=08:59 AM
and it runs for a full week without any problem.
Thanks very much for your reply.
My daily restart time is set to 06:05 AM, and it restarts as expected. So it might not be the issue. Anyway, here is my docker-compose.yml:
version: "3.4"
services:
ib-gateway:
image: ghcr.io/gnzsnz/ib-gateway:stable
restart: always
environment:
TWS_USERID: ${TWS_USERID}
TWS_PASSWORD: ${TWS_PASSWORD}
TRADING_MODE: ${TRADING_MODE:-live}
# VNC_SERVER_PASSWORD: ${VNC_SERVER_PASSWORD:-}
READ_ONLY_API: ${READ_ONLY_API:-}
TWOFA_TIMEOUT_ACTION: ${TWOFA_TIMEOUT_ACTION:-exit}
AUTO_RESTART_TIME: ${AUTO_RESTART_TIME:-}
RELOGIN_AFTER_TWOFA_TIMEOUT: ${RELOGIN_AFTER_TWOFA_TIMEOUT:-no}
TWOFA_EXIT_INTERVAL: ${TWOFA_EXIT_INTERVAL:-60}
TIME_ZONE: ${TIME_ZONE:-Etc/UTC}
CUSTOM_CONFIG: ${CUSTOM_CONFIG:-NO}
# volumes:
# - ${PWD}/jts.ini:/root/Jts/jts.ini
# - ${PWD}/config.ini:/root/ibc/config.ini
ports:
- "127.0.0.1:4001:4001"
- "127.0.0.1:4002:4002"
# - "127.0.0.1:5900:5900"
And here is my .env
file (removed sensitive information):
TWS_USERID=XXX
TWS_PASSWORD=XXX
TRADING_MODE=paper
READ_ONLY_API=no
TWOFA_TIMEOUT_ACTION=restart
AUTO_RESTART_TIME=06:05 AM
RELOGIN_AFTER_2FA_TIMEOUT=yes
TIME_ZONE=Asia/Hong_Kong
CUSTOM_CONFIG=
Thanks.
i haven't noticed that error before. looks like something coming from IBC. it's unlikely that can be fixed on this codebase (ex Dockerfile
or run.sh
), as that's a java exception.
if you find reproduction steps please share them. I'll check my log files to see if I find anything.
hi @josephchenhk
i dug into my log files and indeed I have found the error message that you are reporting. however I can not link it to any actual issue with the functioning of IB Gateway. From my side I can say I have the error on the logs but It does not seems to be causing any issue on my side, or at least I have not noticed it.
have you checked the application logs? ex File>Gateway Logs
Hi @gnzsnz
Thanks for the info. It seems that ib will disconnect for a while and reconnect automatically. If you are not placing an order, it should be fine; but if you are in the middle of placing an order, sometimes it will fail to receive a callback of the order.
can you tell me how to extract the application logs from the docker? Let me get the logs and take a further look. Thanks.
to extract application logs, you need to connet through VNC, and then click File>Gateway Logs
that will save a .txt file named gateway-exported-logs.txt
then you can get it with
docker cp ibgateway:/root/gateway-exported-logs.txt .
ibgateway
is the name of your container
regarding this disconnect, I have noticed, but never really caused me an issue. but i read about it in https://groups.io/g/insync I'm sure you will find something usefull there.
thanks a lot for sharing the link, that's useful.
I didn't connect through VNC at the moment; I guess I can not click and save the logs at this time. But I will turn it on next time and download the logs when I see the disconnection.
Hi @gnzsnz,
I'm facing the same issue here. It seems the java error only occures in case of an reconnect. Whether the connection is closed and restarted during the daily reconnect at 11:45 PM in my case or the connection is closed by peer due to no trading activity.
But, the error does not appear on my API Gateway Logs which I exported via VNC. It's only inside the docker logs.
2023-11-08 23:45:07:133 IBC: Starting Gateway
2023-11-08 23:45:11:612 IBC: Getting config dialog
2023-11-08 23:45:11:613 IBC: Creating config dialog future
2023-11-08 23:45:11:624 IBC: Getting config dialog
2023-11-08 23:45:11:626 IBC: Getting config dialog
2023-11-08 23:45:11:628 IBC: Waiting for config dialog future to complete
2023-11-08 23:45:11:629 IBC: Waiting for config dialog future to complete
2023-11-08 23:45:11:630 IBC: Getting main window
2023-11-08 23:45:11:630 IBC: Creating main window future
2023-11-08 23:45:11:658 IBC: Getting config dialog
2023-11-08 23:45:11:659 IBC: Waiting for config dialog future to complete
java.lang.InterruptedException
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:998)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
at com.sun.javafx.application.PlatformImpl.waitForStart(PlatformImpl.java:256)
at com.sun.javafx.application.PlatformImpl.runLater(PlatformImpl.java:277)
at com.sun.javafx.application.PlatformImpl.runLater(PlatformImpl.java:268)
at com.sun.javafx.application.PlatformImpl.checkIdle(PlatformImpl.java:392)
at com.sun.javafx.application.PlatformImpl.setImplicitExit(PlatformImpl.java:346)
at javafx.application.Platform.setImplicitExit(Platform.java:138)
at twslaunch.gstat.j.a(j.java:88)
at twslaunch.gstat.a.d(a.java:215)
at twslaunch.gstat.a.g(a.java:117)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2023-11-08 23:45:18:639 IBC: detected frame entitled: Loading...; event=Opened
2023-11-08 23:45:18:641 IBC: Found Gateway main window
2023-11-08 23:45:18:643 IBC: Got main window from future
2023-11-08 23:45:18:643 IBC: Invoking config dialog menu
2023-11-08 23:45:18:688 IBC: detected frame entitled: Loading...; event=Activated
2023-11-08 23:45:18:689 IBC: detected frame entitled: Loading...; event=Focused
2023-11-08 23:45:18:689 IBC: detected frame entitled: Loading...; event=Lost focus
2023-11-08 23:45:18:690 IBC: detected frame entitled: Loading...; event=Deactivated
2023-11-08 23:45:18:691 IBC: detected frame entitled: IB Gateway; event=Activated
2023-11-08 23:45:18:703 IBC: detected frame entitled: IB Gateway; event=Focused
2023-11-08 23:45:18:703 IBC: detected frame entitled: IB Gateway; event=Opened
2023-11-08 23:45:18:703 IBC: Login dialog WINDOW_OPENED: LoginState is LOGGED_OUT
2023-11-08 23:45:18:931 IBC: detected frame entitled: IB Gateway; event=Lost focus
2023-11-08 23:45:18:932 IBC: detected frame entitled: IB Gateway; event=Deactivated
2023-11-08 23:45:18:932 IBC: detected frame entitled: Authenticating...; event=Activated
2023-11-08 23:45:18:933 IBC: detected frame entitled: Authenticating...; event=Focused
2023-11-08 23:45:18:933 IBC: detected frame entitled: Authenticating...; event=Opened
LogModuleConfigurator-Init: Log4j Ver2.x found on classpath
LogModuleConfigurator-Init: LogModuleConfigurator initialized with Log4j Verd.x
2023-11-08 23:45:31:171 IBC: detected frame entitled: Starting application...; event=Lost focus
2023-11-08 23:45:31:263 IBC: detected dialog entitled: Trader Workstation Configuration; event=Opened
2023-11-08 23:45:31:264 IBC: detected frame entitled: Starting application...; event=Deactivated
2023-11-08 23:45:31:264 IBC: Got config dialog from future
2023-11-08 23:45:31:264 IBC: Got config dialog from future
2023-11-08 23:45:31:265 IBC: Got config dialog from future
2023-11-08 23:45:31:264 IBC: Got config dialog from future
2023-11-08 23:45:31:264 IBC: detected dialog entitled: Trader Workstation Configuration; event=Activated
2023-11-08 23:45:31:269 IBC: detected dialog entitled: Trader Workstation Configuration; event=Focused
2023-11-08 23:45:31:373 IBC: detected dialog entitled: Trader Workstation Configuration; event=Lost focus
2023-11-08 23:45:31:379 IBC: detected frame entitled: Starting application...; event=Closed
2023-11-08 23:45:31:380 IBC: Login has completed
2023-11-08 23:45:31:382 IBC: detected dialog entitled: Trader Workstation Configuration; event=Focused
2023-11-08 23:45:31:382 IBC: Setting Auto restart time
2023-11-08 23:45:31:514 IBC: Auto restart time already set to 11:45 PM
2023-11-08 23:45:31:515 IBC: Setting ReadOnlyApi
2023-11-08 23:45:31:903 IBC: Read-Only API checkbox is already set to: false
2023-11-08 23:45:31:903 IBC: Performing port configuration
2023-11-08 23:45:31:904 IBC: TWS API socket port is already set to 4000
2023-11-08 23:45:31:904 IBC: Performing master client ID configuration
2023-11-08 23:45:31:904 IBC: TWS Master Client ID is already set to 0
2023-11-08 23:45:32:096 IBC: Configuration tasks completed
2023-11-08 23:45:32:096 IBC: Click button: OK
2023-11-08 23:45:32:236 IBC: detected dialog entitled: Pending Tasks; event=Closed
2023-11-08 23:45:32:237 IBC: detected dialog entitled: Trader Workstation Configuration; event=Lost focus
2023-11-08 23:45:32:238 IBC: detected dialog entitled: Trader Workstation Configuration; event=Deactivated
2023-11-08 23:45:32:238 IBC: detected dialog entitled: Trader Workstation Configuration; event=Closed
addLogConsole Client 2147483647
addLogConsole Client 0
addLogConsole Client 5
addLogConsole Client 5
addLogConsole Client 2147483647
addLogConsole Client 0
2023-11-09 06:14:07:847 IBC: detected frame entitled: Connecting to server...; event=Opened
2023-11-09 06:14:07:849 IBC: detected frame entitled: Connecting to server...; event=Activated
2023-11-09 06:14:07:850 IBC: detected frame entitled: Connecting to server...; event=Focused
addLogConsole Client 5
addLogConsole Client 0
java.lang.InterruptedException
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:998)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
at com.sun.javafx.application.PlatformImpl.waitForStart(PlatformImpl.java:256)
at com.sun.javafx.application.PlatformImpl.runLater(PlatformImpl.java:277)
at com.sun.javafx.application.PlatformImpl.runLater(PlatformImpl.java:268)
at com.sun.javafx.application.PlatformImpl.checkIdle(PlatformImpl.java:392)
at com.sun.javafx.application.PlatformImpl.setImplicitExit(PlatformImpl.java:346)
at javafx.application.Platform.setImplicitExit(Platform.java:138)
at twslaunch.gstat.j.a(j.java:88)
at twslaunch.gstat.a.d(a.java:215)
at twslaunch.gstat.a.g(a.java:117)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2023-11-09 06:15:44:289 IBC: detected frame entitled: Starting application...; event=Lost focus
2023-11-09 06:15:44:289 IBC: detected frame entitled: Starting application...; event=Deactivated
2023-11-09 06:15:44:290 IBC: detected frame entitled: Starting application...; event=Closed
addLogConsole Client 0
addLogConsole Client 2147483647
addLogConsole Client 5
addLogConsole Client 9
2023-11-09 06:59:32:893 IBC: detected frame entitled: IB Gateway; event=Activated
Do you have any thoughts on this issue? Thanks in advance.
thanks for sharing this @ValentinBaier
As far as I can tell, this is just a warning on the logs. I don't have any impact, at least on my side.
last night it happened like 3-4 times with no activity at all, and this morning everything works fine. it happened before and after the daily restart. I just got some fresh historical data and all works fine.
In any case, there is nothing that i can do to fix it. it's coming from IBC, if there is anything to fix it should be fixed upstream. I will re-label this as wontfix
, as this is not a bug related to ib-gateway-docker.
I manage to identify this issue while I was connected throgh VNC
with error message in logs
quant-ibgateway-1 | 2023-11-18T14:15:10.952037425+01:00 2023-11-18 14:15:10:951 IBC: detected dialog entitled: Existing session detected; event=Opened
quant-ibgateway-1 | 2023-11-18T14:15:10.952171156+01:00 2023-11-18 14:15:10:952 IBC: Continue this session and let the other session exit (scenario 5)
quant-ibgateway-1 | 2023-11-18T14:15:10.952304026+01:00 2023-11-18 14:15:10:952 IBC: Click button: Reconnect This Session
quant-ibgateway-1 | 2023-11-18T14:15:11.027317665+01:00 2023-11-18 14:15:11:027 IBC: detected frame entitled: Attempt 3: Authenticating (trying for another 15 seconds)...; event=Lost focus
quant-ibgateway-1 | 2023-11-18T14:15:11.027722907+01:00 2023-11-18 14:15:11:027 IBC: detected frame entitled: Attempt 3: Authenticating (trying for another 15 seconds)...; event=Deactivated
quant-ibgateway-1 | 2023-11-18T14:15:11.028028511+01:00 2023-11-18 14:15:11:027 IBC: detected dialog entitled: Existing session detected; event=Activated
quant-ibgateway-1 | 2023-11-18T14:15:11.029156290+01:00 2023-11-18 14:15:11:029 IBC: detected dialog entitled: Existing session detected; event=Focused
quant-ibgateway-1 | 2023-11-18T14:15:11.030148796+01:00 2023-11-18 14:15:11:030 IBC: detected dialog entitled: Existing session detected; event=Lost focus
quant-ibgateway-1 | 2023-11-18T14:15:11.030853691+01:00 2023-11-18 14:15:11:030 IBC: detected dialog entitled: Existing session detected; event=Deactivated
quant-ibgateway-1 | 2023-11-18T14:15:11.031682689+01:00 2023-11-18 14:15:11:031 IBC: detected dialog entitled: Existing session detected; event=Closed
quant-ibgateway-1 | 2023-11-18T14:15:11.031818264+01:00 2023-11-18 14:15:11:031 IBC: detected frame entitled: Attempt 3: Authenticating (trying for another 15 seconds)...; event=Activated
quant-ibgateway-1 | 2023-11-18T14:15:11.032368338+01:00 2023-11-18 14:15:11:032 IBC: detected frame entitled: Attempt 3: Authenticating (trying for another 15 seconds)...; event=Focused
quant-ibgateway-1 | 2023-11-18T14:15:11.523906339+01:00 java.lang.InterruptedException
quant-ibgateway-1 | 2023-11-18T14:15:11.523976831+01:00 at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:998)
quant-ibgateway-1 | 2023-11-18T14:15:11.523993472+01:00 at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
quant-ibgateway-1 | 2023-11-18T14:15:11.524006236+01:00 at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
quant-ibgateway-1 | 2023-11-18T14:15:11.524018048+01:00 at com.sun.javafx.application.PlatformImpl.waitForStart(PlatformImpl.java:256)
quant-ibgateway-1 | 2023-11-18T14:15:11.524233233+01:00 at com.sun.javafx.application.PlatformImpl.runLater(PlatformImpl.java:277)
quant-ibgateway-1 | 2023-11-18T14:15:11.524272156+01:00 at com.sun.javafx.application.PlatformImpl.runLater(PlatformImpl.java:268)
quant-ibgateway-1 | 2023-11-18T14:15:11.524287795+01:00 at com.sun.javafx.application.PlatformImpl.checkIdle(PlatformImpl.java:392)
quant-ibgateway-1 | 2023-11-18T14:15:11.524301561+01:00 at com.sun.javafx.application.PlatformImpl.setImplicitExit(PlatformImpl.java:346)
quant-ibgateway-1 | 2023-11-18T14:15:11.524308945+01:00 at javafx.application.Platform.setImplicitExit(Platform.java:138)
quant-ibgateway-1 | 2023-11-18T14:15:11.524314997+01:00 at twslaunch.gstat.j.a(j.java:88)
quant-ibgateway-1 | 2023-11-18T14:15:11.524321809+01:00 at twslaunch.gstat.a.d(a.java:215)
quant-ibgateway-1 | 2023-11-18T14:15:11.524328792+01:00 at twslaunch.gstat.a.g(a.java:117)
quant-ibgateway-1 | 2023-11-18T14:15:11.524335946+01:00 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
quant-ibgateway-1 | 2023-11-18T14:15:11.524346055+01:00 at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
quant-ibgateway-1 | 2023-11-18T14:15:11.524359340+01:00 at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
quant-ibgateway-1 | 2023-11-18T14:15:11.524375110+01:00 at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
quant-ibgateway-1 | 2023-11-18T14:15:11.524392632+01:00 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
quant-ibgateway-1 | 2023-11-18T14:15:11.524404284+01:00 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
quant-ibgateway-1 | 2023-11-18T14:15:11.524415125+01:00 at java.lang.Thread.run(Thread.java:748)
quant-ibgateway-1 | 2023-11-18T14:15:11.566467618+01:00 2023-11-18 14:15:11:566 IBC: detected frame entitled: Starting application...; event=Lost focus
quant-ibgateway-1 | 2023-11-18T14:15:11.566516870+01:00 2023-11-18 14:15:11:566 IBC: detected frame entitled: Starting application...; event=Deactivated
quant-ibgateway-1 | 2023-11-18T14:15:11.566756821+01:00 2023-11-18 14:15:11:566 IBC: detected frame entitled: Starting application...; event=Closed
this is caused by a disconnection with IBKR API servers and data servers (not shown on the screenshot)
This confirms that this is not an issue with ib-gateway-docker but an issue comming from IBKR server farm.
@gnzsnz Thanks for your further info.
So if you place an order during this disconnection, can the order be executed normally? If not, what can we do to make sure the order executed as expected? From your log, I can see the interruption started at 2023-11-18 14:15:11:032, and it tried to resume at 2023-11-18 14:15:11:566. Does it mean the interruption only last for half the second? OR it will last for longer since it still take more time for IBC to finish login after detecting the frames. Thanks.
i'm my case it was constantly trying to reconnect, that's how I had time to take the screenshot.
I don't know about the specific case of open orders during a disconnect, maybe https://groups.io/g/insync can help.
Ib-gateway & IBC are doing their job, they try to reconnect.
Got it. Thanks very much. Will post here if I have any further findings.
Describe the bug A clear and concise description of what the bug is.
To Reproduce follow all standard steps and run docker in Debian 7. Everthing works fine; but sometimes after a few hours, will disconnect and see the following error:
Expected behavior The connection should stay active; if it is interrupted, it should be able to resume automatically.
Container logs If applicable, add the container logs
docker logs <CONTAINER>
ordocker-compose logs
to help explain your problem.Versions (please complete the following information):
docker --version
): [e.g. latest]docker images --digests
): [e.g. sha256:60d9d54009b1b66908bbca1ebf5b8a03a39fe0cb35c2ab4023f6e41b55d17894]Additional context Add any other context about the problem here.
Any ideas? Thanks.