search

IbcAlpha / IBC

Automation of Interactive Brokers TWS. You can download the latest release here: https://github.com/ibcalpha/ibc/releases/latest
GNU General Public License v3.0
1.06k stars 185 forks source link

Exiting with "Attempted to append to non-started appender e" #49

Closed tredondo closed 5 years ago

tredondo commented 5 years ago

I'm running IBC Alpha on an Ubuntu VPS with Xvfb, trying to keep the Gateway running as long as possible, logged into my paper trading account. The problem is that IBC Alpha exits after about a day after I launch it with DISPLAY=:0 /opt/ibc/gatewaystart.sh.

Here's one of the logs. Happy to provide any other information.

================================================================================

Starting IBC version 3.7.5 on 2019-04-16 at 11:43:52

Operating system: Linux dd.com 4.18.16-x86_64-linode118 #1 SMP PREEMPT Mon Oct 29 15:38:25 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

Arguments:

TWS version = 975
Entry point = ibcalpha.ibc.IbcGateway
--tws-path = /home/mp/Jts
--tws-settings-path = /home/mp/Jts
--ibc-path = /opt/ibc
--ibc-ini = /home/mp/ibc/config.ini
--mode = 
--java-path = 
--user =
--pw =
--fix-user =
--fix-pw =

=================================
Generating the classpath
Classpath=/home/mp/Jts/ibgateway/975/jars/jts4launch-975.jar:/home/mp/Jts/ibgateway/975/jars/locales.jar:/home/mp/Jts/ibgateway/975/jars/log4j-api-2.5.jar:/home/mp/Jts/ibgateway/975/jars/log4j-core-2.5.jar:/home/mp/Jts/ibgateway/975/jars/total-2018.jar:/home/mp/Jts/ibgateway/975/jars/twslaunch-975.jar:/home/mp/Jts/ibgateway/975/jars/twslaunch-install4j-1.9.jar:/opt/ibc/IBC.jar

Generating the JAVA VM options
Java VM Options=-XX:+UseG1GC -XX:MaxGCPauseMillis=200 -XX:ParallelGCThreads=20 -XX:ConcGCThreads=5 -XX:InitiatingHeapOccupancyPercent=70 -Xmx768m

Determining the location of java executable
Location of java executable=/home/mp/.i4j_jres/1.8.0_152_64/bin

Starting Gateway with this command:
"/home/mp/.i4j_jres/1.8.0_152_64/bin/java" -cp "/home/mp/Jts/ibgateway/975/jars/jts4launch-975.jar:/home/mp/Jts/ibgateway/975/jars/locales.jar:/home/mp/Jts/ibgateway/975/jars/log4j-api-2.5.jar:/home/mp/Jts/ibgateway/975/jars/log4j-core-2.5.jar:/home/mp/Jts/ibgateway/975/jars/total-2018.jar:/home/mp/Jts/ibgateway/975/jars/twslaunch-975.jar:/home/mp/Jts/ibgateway/975/jars/twslaunch-install4j-1.9.jar:/opt/ibc/IBC.jar" -XX:+UseG1GC -XX:MaxGCPauseMillis=200 -XX:ParallelGCThreads=20 -XX:ConcGCThreads=5 -XX:InitiatingHeapOccupancyPercent=70 -Xmx768m ibcalpha.ibc.IbcGateway "/home/mp/ibc/config.ini"  

2019-04-16 11:43:53:145 IBC: Properties file /home/mp/IBC/config.ini not found
System Properties
------------------------------------------------------------
java.runtime.name = Java(TM) SE Runtime Environment
sun.boot.library.path = /home/mp/.i4j_jres/1.8.0_152_64/lib/amd64
java.vm.version = 25.152-b16
java.vm.vendor = Oracle Corporation
java.vendor.url = http://java.oracle.com/
path.separator = :
java.vm.name = Java HotSpot(TM) 64-Bit Server VM
file.encoding.pkg = sun.io
user.country = US
sun.java.launcher = SUN_STANDARD
sun.os.patch.level = unknown
java.vm.specification.name = Java Virtual Machine Specification
user.dir = /home/mp/Jts
java.runtime.version = 1.8.0_152-b16
java.awt.graphicsenv = sun.awt.X11GraphicsEnvironment
java.endorsed.dirs = /home/mp/.i4j_jres/1.8.0_152_64/lib/endorsed
os.arch = amd64
java.io.tmpdir = /tmp
line.separator = 

java.vm.specification.vendor = Oracle Corporation
os.name = Linux
sun.jnu.encoding = UTF-8
java.library.path = /usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
java.specification.name = Java Platform API Specification
java.class.version = 52.0
sun.management.compiler = HotSpot 64-Bit Tiered Compilers
os.version = 4.18.16-x86_64-linode118
user.home = /home/mp
user.timezone = America/Los_Angeles
java.awt.printerjob = sun.print.PSPrinterJob
file.encoding = UTF-8
java.specification.version = 1.8
java.class.path = /home/mp/Jts/ibgateway/975/jars/jts4launch-975.jar:/home/mp/Jts/ibgateway/975/jars/locales.jar:/home/mp/Jts/ibgateway/975/jars/log4j-api-2.5.jar:/home/mp/Jts/ibgateway/975/jars/log4j-core-2.5.jar:/home/mp/Jts/ibgateway/975/jars/total-2018.jar:/home/mp/Jts/ibgateway/975/jars/twslaunch-975.jar:/home/mp/Jts/ibgateway/975/jars/twslaunch-install4j-1.9.jar:/opt/ibc/IBC.jar
user.name = mp
java.vm.specification.version = 1.8
sun.java.command = ibcalpha.ibc.IbcGateway /home/mp/ibc/config.ini
java.home = /home/mp/.i4j_jres/1.8.0_152_64
sun.arch.data.model = 64
user.language = en
java.specification.vendor = Oracle Corporation
awt.toolkit = sun.awt.X11.XToolkit
java.vm.info = mixed mode
java.version = 1.8.0_152
java.ext.dirs = /home/mp/.i4j_jres/1.8.0_152_64/lib/ext:/usr/java/packages/lib/ext
sun.boot.class.path = /home/mp/.i4j_jres/1.8.0_152_64/lib/resources.jar:/home/mp/.i4j_jres/1.8.0_152_64/lib/rt.jar:/home/mp/.i4j_jres/1.8.0_152_64/lib/sunrsasign.jar:/home/mp/.i4j_jres/1.8.0_152_64/lib/jsse.jar:/home/mp/.i4j_jres/1.8.0_152_64/lib/jce.jar:/home/mp/.i4j_jres/1.8.0_152_64/lib/charsets.jar:/home/mp/.i4j_jres/1.8.0_152_64/lib/jfr.jar:/home/mp/.i4j_jres/1.8.0_152_64/classes
java.vendor = Oracle Corporation
file.separator = /
java.vendor.url.bug = http://bugreport.sun.com/bugreport/
sun.io.unicode.encoding = UnicodeLittle
sun.cpu.endian = little
sun.cpu.isalist = 
------------------------------------------------------------
2019-04-16 11:43:53:153 IBC: Using default settings provider: ini file is /home/mp/ibc/config.ini
2019-04-16 11:43:53:153 IBC: Using default login manager: getting username and password from args but not found. Will get from settings
2019-04-16 11:43:53:153 IBC: Using default main window manager: constructor parameter isGateway=true
2019-04-16 11:43:53:154 IBC: Using default trading mode manager: constructor parameter args but trading mode not present - will be taken from settings
2019-04-16 11:43:53:156 IBC: Using default config dialog manager
2019-04-16 11:43:53:164 IBC: CommandServer is not started because the port is not configured
2019-04-16 11:43:53:380 IBC: TWS Settings directory is: /home/mp/Jts
2019-04-16 11:43:53:383 IBC: Ensuring /home/mp/Jts/jts.ini contains required minimal lines
2019-04-16 11:43:53:383 IBC: Found section: [Logon]
2019-04-16 11:43:53:383 IBC: Can't find setting: s3store=false
2019-04-16 11:43:53:383 IBC: Found section: [Logon]
2019-04-16 11:43:53:384 IBC: Found setting: s3store=true
2019-04-16 11:43:53:384 IBC: Found section: [IBGateway]
2019-04-16 11:43:53:384 IBC: Found setting: ApiOnly=true
2019-04-16 11:43:53:384 IBC: Confirmed /home/mp/Jts/jts.ini contains required minimal lines
2019-04-16 11:43:59:521 IBC: Detected frame entitled: IB Gateway; event=Activated
2019-04-16 11:43:59:532 IBC: Detected frame entitled: IB Gateway; event=Opened
2019-04-16 11:43:59:536 IBC: Trading mode from settings: tradingMode=paper
2019-04-16 11:43:59:536 IBC: Setting Trading mode = paper
2019-04-16 11:43:59:739 IBC: Click button: Paper Log In
2019-04-16 11:44:01:316 IBC: Detected frame entitled: IB Gateway.  API Account: atol1358; event=Opened
2019-04-16 11:44:01:316 IBC: Found Gateway main window
2019-04-16 11:44:01:319 IBC: Detected frame entitled: IB Gateway.  API Account: atol1358; event=Activated
2019-04-16 11:44:01:708 IBC: Detected frame entitled: Authenticating...; event=Activated
2019-04-16 11:44:01:709 IBC: Detected frame entitled: Authenticating...; event=Opened
LogModuleConfigurator-Init: Log4j Ver2.x found on classpath
LogModuleConfigurator-Init: LogModuleConfigurator initialized with Log4j Verd.x
2019-04-16 11:44:08:749 IBC: Detected frame entitled: Starting application...; event=Closed
2019-04-16 11:44:09:079 IBC: Detected dialog entitled: Warning; event=Activated
2019-04-16 11:44:09:095 IBC: Detected dialog entitled: Warning; event=Opened
2019-04-16 11:44:09:095 IBC: Click button: I understand and accept
2019-04-16 11:44:09:209 IBC: Detected dialog entitled: Warning; event=Closed
remove Client 30
2019-04-16 21:40:31:279 IBC: Detected frame entitled: DUXXXXXX Exit Session Setting (Simulated Trading); event=Activated
2019-04-16 21:40:31:290 IBC: Detected frame entitled: DUXXXXXX Exit Session Setting (Simulated Trading); event=Opened
2019-04-16 21:45:01:463 IBC: Detected dialog entitled: Shutdown progress; event=Opened
2019-04-16 21:45:01:467 IBC: Detected dialog entitled: Shutdown progress; event=Activated
2019-04-16 21:45:01:509 IBC: Detected frame entitled: DUXXXXXX Exit Session Setting (Simulated Trading); event=Closed
2019-04-16 23:45:03,442 JTS-IA Stopper-105 ERROR Attempted to append to non-started appender e
2019-04-16 23:45:03,445 NIA-Input-Queue-2 ERROR Attempted to append to non-started appender e
2019-04-16 23:45:03,446 NIA-Input-Queue-2 ERROR Attempted to append to non-started appender e
2019-04-16 23:45:03,574 JTS-IA-Usage-Reporter-1 ERROR Attempted to append to non-started appender e
Gateway finished
rlktradewright commented 5 years ago

The thing to note is that the "Attempted to append to non-started appender e" messages are actually output to StdOut by the Gateway itself when it shuts down: they're not anything to do with IBC (but IBC logs any output to StdOut).

So the Gateway has simply decided to shut down here. What's odd is the 'Detected frame entitled: DUXXXXXX Exit Session Setting' message. I've never seen the Gateway display this dialog before, only TWS, which displays it a few minutes before the configured autologoff time.

Perhaps this is some new behaviour in Gateway 975? I havent actually got round to testing 975 yet, so it looks like I'd better get started with it, and see if i can understand what's happening here.

In the meantime I suggest you revert to 974, unless there is something new in 975 that you need.

tredondo commented 5 years ago

Thanks for looking into this.

I couldn't find 974 among the downloads but I've reverted to 972.1s.

rlktradewright commented 5 years ago

Ok, I've checked this out, and unfortunately IBKR have introduced the autologoff mechanism into the Gateway, the same as TWS.

And, like TWS, if you start Gateway from the ibgateway.exe program or the desktop icon (or the Linux script), you can use the 'Auto restart' option to keep it running all week.

However, IBC can't work with the .exe/script: it is limited to invoking Gateway via the relevant Java entrypoint, and doing so doesn't offer the 'Auto restart' option.

So, as with TWS 974 onwards, if you want to use Gateway 975 with IBC and keep it running, you'll have to set the autologoff time to an appropriate value and arrange to restart IBC automatically every day shortly after that time.

Note that this will of course mean that your API applications have to be able to cope with disconnections from Gateway.

The only alternative is to give up using IBC with Gateway and run it from the .exe (or Linux script). This of course means you'll have to login manually once a week.

tredondo commented 5 years ago

I saw this error again today, while using Gateway 972.1t on Ubuntu. I understand the error is generated by Gateway, so there might be nothing IBC could do, but in case there is, I've attached the log of this new occurrence.

appender_log_2019-07-04.txt

rlktradewright commented 5 years ago

No there is nothing you can do about this error message. Just ignore it.

You already gave me the log, so why post it again?

And in future, please attach log files rather than quoting them.

tredondo commented 5 years ago

Sorry about that. Cleaner indeed to attach the log; I've edited my comment above.

The reason I posted the new log was in hope it would help identify anything IBC could do to improve the situation. The first log I posted seemed useful,

What's odd is the 'Detected frame entitled: DUXXXXXX Exit Session Setting' message. I've never seen the Gateway display this dialog before