[ts-gen] questions on journal tables

[Bill Pippin]

Nils,

> For one occasion I observed shim to produce the following output: 
 
> Oreq:  0x7f37c96c9660  0x7f381acd1dc0  0x7f381acc6738
> Oreq:  0x7f37c974b8d8  0x7f381acd1dc0  0x7f381acc6738
 
> Problem: 414 mysql query evaluation failed
> Error 1062 (23000): Duplicate entry 'exit2009_0430_123253' for key 2
> call OrderUpdate('exit2009_0430_123253', 2, 48824, 78, 1, 8, 142,
> 'test_e', null, 'create', 'LMT', 5, 0.0, 123, NULL, NULL, NULL);
> Problem: 417 %s tuple not found following insert
> Oreq:  0x7f37c7cafd50  0x7f381acd1dc0  0x7f381acc6738

First, I'll interpret your stderr trace outputs in turn; they fall
into three categories: innocuous output from the shim; a 414 warning
for a sql error, with accompanying error output obtained from Mysql;
and the follow-on 417 warning of a ghost insert, predictable given
the specifics of the 414.

The lines prefixed by the order request tag text, "Oreq", are
innocuous; if any of the hex addresses was nil, then that would be
the first sign of some internal problems, but the addresses are
non-null, and in fact this printf has been commented out in later
versions of the shim.

Second, Mysql is complaining that an insert statement in the
OrderUpdate stored procedure would break a unique key constraint
for one of the tables that it brackets in a transaction, either
CreateEvent or ChangeOrder.

Here's most of the stored procedure code, from sql/proc.sql:

  declare eid   int unsigned;

  start transaction;
    insert
      into CreateEvent
           (var, oid, tag, route, acc, client_id, order_tag, mark, oca)
    values (var, oid, tag, route, acc, client_id, order_tag, mark, oca);

    set eid = last_insert_id();

    insert
      into ChangeOrder
           (eid, act, ord_type, quantity, lmt_price, aux_price, gat, ...
    values (eid, act, ord_type, quantity, lmt_price, aux_price, gat, ...
  commit;

Looking at the create table statements in sql/xact.sql, CreateEvent has
as unique keys "uid" and "var", and ChangeOrder only "uid", and the
stored procedure code is letting Mysql set the uid indices.  So, by
process of elimination, the duplicate key value is for the "var"
attribute of CreateEvent.

Looking also at the error text from mysql, we see that your order key
'exit2009_0430_123253' has been seen before, so we can come to the
same conclusion --- an order key is being reused --- from either of
two lines of analysis.

Finally, the 417 warning merely reflects the fact that the shim
could not reread the record it tried to insert.  Though sometimes
innocuous, here a 417 means that the foundation record for an entire
order has never reached the database, and furthur journalling for
the order will be unfounded; or possibly that two orders have been
conflated.  Not good; the shim really needs unique keys per order.

So, I suspect there is a problem with your downstream code.  This is
not certain --- all we know for certain is that the shim is trying to
insert an order key it has inserted before --- but the easiest way to
create this problem is to give the shim two "create item" commands
with the same order key, and I'm not aware of any way the shim could
perform two inserts for a single request.

You'll probably recall a year or two back that you identified an error 
leading to duplicate requests.  I don't believe this is happening here,
but if it is, it should be consistently so.  I very much doubt that the
shim is intermittently replaying create order commands, or duplicating
the resulting requests.  In any case, your log file should let you see
what is happending; are two requests going out for the same order, or
does your downstream code accidently reuse an order key?

Please let us know.

Thanks,

Bill