[ts-gen] OrderStatus inserts missing [Was: OrderStatus dups ...]

Nils Gebhardt mail at ngebhardt.de
Mon Aug 24 15:22:09 EDT 2009



in the following I try to collect some more information on this topic. 


On Fri, 2009-08-21 at 18:03 -0400, Bill Pippin wrote:


What api level are you working with; more precisely, what api level
> does the IB tws offer, and is the shim working at api level 23?
> What build of the IB tws are you using?  By way of example, when I 
> choose Help->About Trader Workstation, the panel that appears
> includes the text "Build 897.6, Aug 4, 2009 9:23:37 AM"; is yours
> newer or older than that, and what is it?
> 
> 
from the startup banner in the tws logs: 

BN 07:13:31:514 JTS-Main: ------------------------------- TWS RESTART
--------------------------------
BN 07:13:31:592 JTS-Main: Jts dir is ./
BN 07:13:31:695 JTS-Main: Region:Europe dr:false
BN 07:13:31:705 JTS-Main: Property locale_to_use=en
BN 07:13:31:724 JTS-Main: JTS Locale=en_US  country=United States
variant=
BN 07:13:31:724 JTS-Main: Property locale_to_use=en
BN 07:13:31:724 JTS-Main: JTS Locale=en_US  country=United States
variant=
BN 07:13:31:727 JTS-Main: Property locale_to_use=en
BN 07:13:31:727 JTS-Main: JTS Locale=en_US  country=United States
variant=
BN 07:13:31:727 JTS-Main: Locale=en_US  country=United States  variant=
BN 07:13:31:728 JTS-Main: prohibiting class lookup [ji18n.Language]
BN 07:13:32:357 JTS-Main: prohibiting class lookup [ji18n.Language_en]
BN 07:13:32:357 JTS-Main: prohibiting resource lookup
[ji18n/Language_en.properties]
BN 07:13:32:357 JTS-Main: prohibiting class lookup
[ji18n.Language_en_US]
BN 07:13:32:357 JTS-Main: prohibiting resource lookup
[ji18n/Language_en_US.properties]
BN 07:13:32:357 JTS-Main:   actual locale: 
BN 07:13:32:499 JTS-Main: prohibiting class lookup
[org.jfree.chart.LocalizationBundle]
BN 07:13:32:638 JTS-Main: prohibiting class lookup
[org.jfree.chart.LocalizationBundle_en]
BN 07:13:32:638 JTS-Main: prohibiting resource lookup
[org/jfree/chart/LocalizationBundle_en.properties]
BN 07:13:32:638 JTS-Main: prohibiting class lookup
[org.jfree.chart.LocalizationBundle_en_US]
BN 07:13:32:638 JTS-Main: prohibiting resource lookup
[org/jfree/chart/LocalizationBundle_en_US.properties]
BN 07:13:32:638 JTS-Main: prohibiting class lookup
[org.jfree.chart.plot.LocalizationBundle]
BN 07:13:32:646 JTS-Main: prohibiting class lookup
[org.jfree.chart.plot.LocalizationBundle_en]
BN 07:13:32:646 JTS-Main: prohibiting resource lookup
[org/jfree/chart/plot/LocalizationBundle_en.properties]
BN 07:13:32:646 JTS-Main: prohibiting class lookup
[org.jfree.chart.plot.LocalizationBundle_en_US]
BN 07:13:32:647 JTS-Main: prohibiting resource lookup
[org/jfree/chart/plot/LocalizationBundle_en_US.properties]
BN 07:13:33:656 JTS-Main: jfreechart version =1.0.8
BN 07:13:33:657 JTS-Main: jcommon version =1.0.12
BN 07:13:33:678 JTS-Main: plugin support version =1.0
BN 07:13:33:680 JTS-Main: JDOMFactory Class =interface
org.jdom.JDOMFactory
BN 07:13:33:689 JTS-Main: riskfeed typical class = interface
riskfeed.api.RiskFeedITF
BN 07:13:33:707 JTS-Main: hsqldb jdbc =class org.hsqldb.jdbcDriver
BN 07:13:33:833 JTS-Main: LookAndFeelChangedListener installed
BN 07:13:33:847 JTS-Main: JtsLookAndFeel initialized
BN 07:13:34:343 JTS-Main: Current LAF: TWS LAF
BN 07:13:34:345 JTS-Main: java.lang.UnsupportedOperationException:
Toolkit.getLockingKeyState
BN 07:13:34:856 JTS-Main: Started on 20090821-05:13:34
BN 07:13:34:861 JTS-Main: Default timezone:Europe/Berlin name:Central
European Time dst:3600000
BN 07:13:34:990 JTS-Main: Build 893.9, Apr 14, 2009 4:04:04 PM


So appearently I am slightly behind the most recent build version ... 


Can you confirm what stream (downstream command or upstream message)
> and what object (cmd name, msg name) is being read when the above
> text occurs?  I'm ruling out database reads, since the
> out_of_sync_probe_failed message doesn't apply to table reads, where
> the expected table record format is already known.  I also suspect
> that the problem is occurring with messages, since they are so much
> more frequent than commands, and if there was a command syntax error,
> I would expect that you probably would have diagnosed it by now.
> 
> Granted that the token level syntax problem occurs with IB tws api
> messages, then what kinds of messages occur nearby, both previously
> in the log, as well as after?
> 

I can't see anything what seems to be irregular. The following is a
complete sesion: 


 8906|68040|3179938068|4|11| 0|# \nselect open;|
 8906|68040|3179938152|1| 4| 0|\nselect open;|
 8906|68040|3179938185|2| 5| 1|5|1||||
 8906|68056|3204886953|4|11| 0|# create item test_e ibc:46089651 at DTB
take2009_0821_185359 LMT 1 115.51 0.0;|
 8906|68056|3204887349|1|18| 0|create item test_e ibc:46089651 at DTB
take2009_0821_185359 LMT 1 115.51 0.0;|
 8906|68056|3204887662|2| 3|15|3|15|332|GBM|FUT|20090908|0.0000||1|DTB||
EUR||BUY|1|LMT|115.5100|0.0000|GTC||||0|test_e|0||0|0|0|2|1|
0||||||||||||
 8906|68056|3204915979|4|12| 0|# create: FUT:DTB:GBM:EUR: (LMT, 1,
115.5100,   0.0000);|
 8906|68056|3205010630|3| 4| 2|  332|2109|Order Event Warning:Attribute
'Outside Regular Trading Hours' is ignored based on the order type and
destination. PlaceOrder is now being processed.|
 8906|68057|3206261025|4|11| 0|# submit item
take2009_0821_185359;|
 8906|68057|3206261359|1|21| 0|submit item
take2009_0821_185359;|
 8906|68057|3206261657|2| 3|15|3|15|332|GBM|FUT|20090908|0.0000||1|DTB||
EUR||BUY|1|LMT|115.5100|0.0000|GTC||||0|test_e|1||0|0|0|2|1|
0||||||||||||
 8906|68057|3206285472|4|12| 0|# submit: FUT:DTB:GBM:EUR: (LMT, 1,
115.5100,   0.0000);|
 8906|68057|3206348807|1| 8| 0|bind key:exit2009_0821_185417 to oid:2;|
 8906|68057|3206399979|3| 5|10|332|GBM         |FUT|20090908|0.000000||
DTB|EUR|FGBM SEP 09|BUY|1|LMT|115.510000|0.000000|GTC||XXXXXX|C|0|
test_e|8|1989268282|0|0|0.000000||1989268282.0/XXXXXXX/100|||||||
0.000000||0||0|0.000000|0.000000|0.000000|0.000000|0.000000|0|0|0|0|0|0|
3|0|0|0.000000|0|2|
 8906|68057|3206400074|3| 3| 6|332|Submitted|0|1|0.000000|1989268282|0|
0.000000|8|
 8906|68057|3206403283|4|12| 0|# journal OrderStatus(1);|
 8906|68057|3206407234|4|12| 0|# journal ActiveOrder(1);|
 8906|68057|3206700455|4|11| 0|# select open;|
 8906|68057|3206700645|1| 4| 0|select open;|
 8906|68057|3206700735|2| 5| 1|5|1||||
 8906|68057|3206704805|3| 5|10|332|GBM         |FUT|20090908|0.000000||
DTB|EUR|FGBM SEP 09|BUY|1|LMT|115.510000|0.000000|GTC||XXXXXX|C|0|
test_e|8|1989268282|0|0|0.000000||1989268282.0/XXXXXXX/100|||||||
0.000000||0||0|0.000000|0.000000|0.000000|0.000000|0.000000|0|0|0|0|0|0|
3|0|0|0.000000|0|2|
 8906|68057|3206705067|3| 3| 6|332|Submitted|0|1|0.000000|1989268282|0|
0.000000|8|
 8906|68057|3206711244|4|12| 0|# journal OrderStatus(1);|
 8906|68057|3206719516|4|12| 0|# journal ActiveOrder(1);|




Have you included all of the error text produced by the shim?  The
> first and last parts are particularly critical.  One problem here
> is that since the shim is probing for the initial token at the
> beginning of an event --- 404 probe failed tells us that much ---
> and it's hard to tell what exactly has gone wrong, since there is
> so little context.
> 
> 
yes, that is the complete error output. Actually in pre mid july
versions I didn't get any output at all. 


With the file and save options in effect, so that the IB tws binary
> input is copied to log/tws2shim.bin, and using the bin/msg.filter
> script to look at the above binary log, can you tell where in the
> text stream the problem is occurring?  Note, the bin/msg.filter
> script is necessarily imprecise, and by inserting newlines, it may
> well make it harder for you to be sure what's going wrong.  So,
> if you have a text editor than can handle unlimited line lengths,
> such as vi, just piping the tws2shim.bin file through tr to
> replace ascii NULs with bars will convert the file to text, although
> it will all be on one line:
> 
>     cat log/tws2shim.bin | tr '\000' \|
> 
> Then, if are using vi, and you so choose, you can incrementally
> insert your own line breaks using the following greedy approach
> (false positives will occur), e.g., for tick price messages:
> 
>     :%s/|1|5|/^M|1|5|/g
> 
> where the above is typed as colon-percent s-slash
> vertical bar-one-vertical bar-five-vertical bar-slash-CtrlVM ...,
> and Ctrl indicates the control key being held down while you
> type cap V-cap M .
> 
> Cryptic, I agree, but you're working with the raw, binary stream,
> and the IB tws api protocol completely lacks record separators
> or synchronization information, and we have to take what we can
> get here.
> 
> In any case, examining the original binary input may be time
> consuming, and I'm not sure how much you'll be able to understand
> of what you see, but I would like to somehow know what the shim
> was trying to read when it failed, and especially what it did with
> the material that came afterwards.

this is a sample piece of stream fo a missing Filled order status
message


8|1989268226|0|0|0||1989268226.0/XXXX/100|||||||||0||0|||||||0|0|0|0||3|
0|0||0|2|3|6|276|Filled|1|0|122.4|1989268226|0|122.4|
8|5|10|276|GBL|FUT|20090908|0.0|?|DTB|EUR|FGBL SEP 09|BUY|1|LMT|122.4|
0.0|GTC||XXXX|C|0|test_e|8|1989268226|0|0|0|
|1989268226.0/XXXX/100|||||||||0||0|||||||0|0|0|0||3|0|0||0|2|3|6|276|
Filled|1|0|122.4|1989268226|0|122.4|8|6|2|Cushion|0.832593|


 - to be honest I do not understand where it starts and where it ends.
It
follows a account status message. 










> 
> In the below text, we see that the shim was starting to read a
> message or command [probe failed ...], probably read spaces or
> control chars instead, wanted something more, that is a command
> verb or message index number, viewed what it saw as leaving the
> scanner in an error state [scanner saw: err ...], dumped it
> [drop, del], and wondered aloud whether message synchronization
> had been lost, which is particularly a problem with api-level
> conflicts for IB tws messages.
> 
> > For token text: [        ] and type target [Str]
> > predicted token type:  str, scanner saw:  err
> > Problem: 401 unexpected token text: syntax error
> > Problem: 404 probe failed: messages not in sync?
> 
> Keep in mind here that the IB tws just kills the socket connection
> when it has problems reading a request, so that the shim, which
> can recover and resync for messages, is actually working to a higher
> standard of lexical processing.
> 
> The token-level syntax error may not be the only problem, and for
> that matter may not be related to the failed inserts, but I have
> to start somewhere, and the syntax errors certainly are suspicious.
> 
> My first guess is an api level problem, perhaps you're using a
> newer IB tws build and I need to fix one of the grammar rules.
> At this point I can't be sure; as I noted above, I'm using the
> newest one I can get.
> 

I can try to switch to a more recent build during this week. 
I also will reset my database and fix wrong ibc numbers, as you 
explained in a previous posting. 


I can add two more observations, useful or not: 

* I have seen OrderStatus records coming in very late, for example a
Cancel in the morning 
resulting in a record in the afternoon with timestamp from afternoon. 

* Sometimes I can see at startup messages like this, saying something
about OrderStatus: 

          The trading shim has connected to the database server and
          loaded  51620 products.  The IB tws offered api level 44,
          and connection negotiation resulted in an api level of 23
          and a client id of  8.  
Argument type: acc was not found
in source rule msg:Status on behalf of
create target: :OrderStatus
Feed? 1 OrderStatus  acc  acc status 
For msg: Status
Problem: 418 could not post ambiguous order message
A query shows the account code to
          be XXXX.  Program initialization has been completed





That much for the moment, if I can collect more I will put into a
following posting. 


Thanks

Nils



More information about the ts-general mailing list