[ts-gen] OrderStatus dups fixed [Was: OrderStatus dups and skips]

[Bill Pippin]

Nils,

My comments about the fourth point from your feedback on last
week's shim:

> 4) on order status duplications: I had an increasing amount of
> duplications since the second week of july. In the end I had not only
> double items, but also triplets and order status messages repeating
> later on. These records seemed to occur in both data base and
> log/ShimText. Friday they disappeared, using an older version from
> april. The 20090723 didn't show any double items. ...

You may be saying in the above that the shim is now working fine with
respect to order status logging, and we could leave it at that.

For those following along, however, the current situation may seem
unclear, and in particular they might believe that when duplicate order
status messages show up in the log, that those dups are a problem
we should fix.

No can do!  There are two issues here, dup messages in the log, and
dup records in the database.  The first is due to the IB tws, the
second would be the responsibility of the shim.

As you note, there were dups in the journal with most of the releases
this month.  That was a problem with the shim, and it was fixed with
the 20090723 release, including in part the database increment.

The dups in the log remain, and will continue to occur as long as the
IB tws sends them out.  E.g., while running the exs/risk.rb test
script today, I observed the following (truncated and lightly
reformatted) execution report and order status messages:

11| 7|430|AAPL|STK||0.0| |BATS |USD|AAPL|00018037.465208b8.01.01|...
 5|10|430|AAPL|STK||0.0|?|SMART|USD|AAPL|BUY |1|MKT|0.0|0.0|GTC||...
 5|10|430|AAPL|STK||0.0|?|SMART|USD|AAPL|BUY |1|MKT|0.0|0.0|GTC||...
 5|10|430|AAPL|STK||0.0|?|SMART|USD|AAPL|BUY |1|MKT|0.0|0.0|GTC||...

11| 7|431|AAPL|STK||0.0| |NSX  |USD|AAPL|00018037.465208c1.01.01|...
 5|10|431|AAPL|STK||0.0|?|SMART|USD|AAPL|SELL|1|MKT|0.0|0.0|GTC||...
 5|10|431|AAPL|STK||0.0|?|SMART|USD|AAPL|SELL|1|MKT|0.0|0.0|GTC||...
 5|10|431|AAPL|STK||0.0|?|SMART|USD|AAPL|SELL|1|MKT|0.0|0.0|GTC||...

The above extract is typical of what users should expect via the IB
tws api; note that there are three order status messages for each
fill.  This is a longstanding "feature" of the IB tws, and given our
policy of having the shim faithfully represent the message inputs
from the upstream, the shim's log will continue to reflect such dups
as long as the IB tws sends them.

For those who might wonder how I *know* that the dups are due to
the IB tws, and not some internal problem in the shim, there is
a cross check you can make.  With the file and save options on,
the shim stores socket traffic from the upstream in log/tws2shim.bin.
The code to do this is right at the point of input; the same buffer
that the linux read(2) system call fills is immediately written
out to the binary image file.  The bin/msg.filter script can be used
to read the resulting image file, and although it may introduce minor
formatting glitches, it's just a simple tr/sed script and leaves the
number of events unchanged.  Whenever you are uncertain whether you
trust the text log file, you can always check it against the binary
images of the upstream traffic.

There were a number of significant improvements in log file output
with the byte-level request queueing feature of the last month or
so, and I'd like to take this opportunity to describe the current
status of log output; the only existing known problem is with
syntax errors in commands, where, in addition to the copious error
messages on the stderr, the command echo to the log is jumbled.

All events have common prefix and in some cases suffix data, e.g.,
the process pid, log timestamp, and event code {1, 2, 3: cmds, reqs,
and msgs} are common to all events.  Otherwise, the following is true:

    commands: for syntactically correct commands, the log echoes
              their text, with some reordering to reflect queueing.
    requests: faithfully echo the wire format; the same code that
              uses the request object to lay out the request with
              null separators for the upstream, uses vertical bars
              for the log; the only difference is the output stream
              object (Logger or Sender) and the buffer type (NulBuf
              or BarBuf).
    messages: reflect the wire format, though with both whitespace
              formatting and often suffix annotation, e.g., the
              symbol translation for the tick id; the format for
              market data is explained below.

By the way, since request and message logging reflects the wire format,
and that format is documented by IB in the EClientSocket.java and
EReader.java files of their sample client, you can match the attributes
of the api event payload in the log against IB's docs one-for-one.

By "payload" I mean the log event format once stripped of the prefix and
any suffix.  E.g., for market data, and with price data obscured to 
honor IB's license restrictions on redistribution, market data for Apple
in the log recently appeared as follows: 

15481|65972|  0.000017|1| 9| 0|select tick  STK:SMART:AAPL:USD 1;|
15481|65972|  0.000016|2| 1| 5|1|5|1|AAPL|STK||0.0000||1|SMART||USD||||||
15481|65972|  0.022712|1| 2| 0|wait 2;|
15481|65972|  0.229638|3| 1| 5|    1| 1|   1?3.4|       3|1|...
15481|65972|  0.000008|3| 1| 5|    1| 2|   1?3.6|       2|1|...
15481|65972|  0.000004|3| 1| 5|    1| 4|   1?3.6|       1|0|...
15481|65972|  0.000005|3| 2| 5|    1| 0|                3|0|...
15481|65972|  0.000003|3| 2| 5|    1| 3|                2|0|...
15481|65972|  0.000003|3| 2| 5|    1| 5|                1|0|...
15481|65972|  0.000003|3| 2| 5|    1| 8|           179???|0|...
15481|65972|  0.000005|3| 1| 5|    1| 6|   1?5.0|       0|0|...
15481|65972|  0.000004|3| 1| 5|    1| 7|   1?2.9|       0|0|...
15481|65972|  0.000004|3| 1| 5|    1| 9|   1?2.8|       0|0|...
15481|65974|  1.798008|1|10| 0|cancel tick  STK:SMART:AAPL:USD;|
15481|65974|  0.000063|2| 2| 1|2|1|1||||

In the above text, the first four columns are prefix information: the 
process id, seconds since midnight, microseconds, and event type,
here: cmd, req, cmd, 10 market data msgs, cmd, and req.  The message
payloads are repeated below; note that market data price and size
messages have seven and five attributes, respectively:

     1| 5|    1| 1|   1?3.4|       3|1|
     1| 5|    1| 2|   1?3.6|       2|1|
     1| 5|    1| 4|   1?3.6|       1|0|
     2| 5|    1| 0|                3|
     2| 5|    1| 3|                2|
     2| 5|    1| 5|                1|
     2| 5|    1| 8|           179???|
     1| 5|    1| 6|   1?5.0|       0|0|
     1| 5|    1| 7|   1?2.9|       0|0|
     1| 5|    1| 9|   1?2.8|       0|0|

Of course the question marks above are not part of the logging,
and are used herein to avoid running afoul of IB's license
restrictions.  For market data price events, the attributes are
message index, version, tick id, market data subtype, price, 
quantity, and the "can auto execute" flag.  Note also that the
whitespace formatting is not found in the original wire format
data as received over the socket.

The suffix annotation here consists of the 0-value flag padding for
market data size events, the tick subtype explanation, and the tick
id translation of 1 as STK:SMART:AAPL:

    1| 1|   1?3.4|       3|1|price.outcry.bid.   |STK:SMART:AAPL:
    1| 2|   1?3.6|       2|1|price.outcry.ask.   |STK:SMART:AAPL:
    1| 4|   1?3.6|       1|0|price.summary.last. |STK:SMART:AAPL:
    1| 0|                3|0|size.bid.           |STK:SMART:AAPL:
    1| 3|                2|0|size.ask.           |STK:SMART:AAPL:
    1| 5|                1|0|size.last.          |STK:SMART:AAPL:
    1| 8|           1?9494|0|size.volume.        |STK:SMART:AAPL:
    1| 6|   1?5.0|       0|0|price.summary.high. |STK:SMART:AAPL:
    1| 7|   1?2.9|       0|0|price.summary.low.  |STK:SMART:AAPL:
    1| 9|   1?2.8|       0|0|price.summary.close.|STK:SMART:AAPL:

> ... I will watch how it evolves. 

Since I have not yet observed the missing status messages you
ran into --- the problem with dups is understood and fixed, but I've
not seen the drops --- I much appreciate your continued attention.

Thanks,

Bill