Partial order execution is not reported correctly in notify_order

[vladisld]

vladisld 7 Jan 2020, 00:04

Upon live testing my strategy on IB paper account some order are executing partially and several notifications could be received with Order.Partial status before the Order.Completed status notification. I was expecting that iterating the pending exbits of each partial order notification will return me the bits that were relevant for each notification. So for example if the order on the first partial notification had four exbits:

idx:0 size:100 price:10.99
idx:1 size:100 price:10.99
idx:2 size:300 price:10.99
idx:3 size:100 price:10.99

and on the second notification had 6 bits:

idx:0 size:100 price:10.99
idx:1 size:100 price:10.99
idx:2 size:300 price:10.99
idx:3 size:100 price:10.99
idx:4 size:200 price:10.98
idx:5 size:109 price:10.98

the order.executed.iterpending() should return the first four ( idx:0 trough idx:3 ) on the first notification and the next two (idx:4, idx:5) on the second notification. However it's seems not to be the case. Instead, iterating the pending execbits returns all the bits every time ( four bits on the first notification and six on the second)

Looking at the code it looks like the OrderData's p1 and p2 indexes are used to implement the needed behavior and are updated upon order cloning when pushed to the notification queue. So the client code should see the p1 and p2 updated already and OrderData.iterpending() method should reflect that. However it seems that those indexes are not updated. Below I've logged the order data including the p1 and p2 indexes:

2020-01-06 12:18:35:HMI-STK-SMART-USD:track::notify_order: Limit Buy Partial, price: 10.99, size: 600, cost: 6594.0, comm: 3.0, ref: 6
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::order bits: p1: 0, p2: 4
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::idx: 0, dt: 2020-01-06 12:18:42, bit size:100, bit price:10.99
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::idx: 1, dt: 2020-01-06 12:18:42, bit size:100, bit price:10.99
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::idx: 2, dt: 2020-01-06 12:18:42, bit size:300, bit price:10.99
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::idx: 3, dt: 2020-01-06 12:18:43, bit size:100, bit price:10.99
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::order bits done.
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::notify_order: Limit Buy Partial, price: 10.9875, size: 800, cost: 8790.0, comm: 4.0, ref: 6
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::order bits: p1: 0, p2: 5
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::idx: 0, dt: 2020-01-06 12:18:42, bit size:100, bit price:10.99
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::idx: 1, dt: 2020-01-06 12:18:42, bit size:100, bit price:10.99
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::idx: 2, dt: 2020-01-06 12:18:42, bit size:300, bit price:10.99
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::idx: 3, dt: 2020-01-06 12:18:43, bit size:100, bit price:10.99
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::idx: 4, dt: 2020-01-06 12:18:44, bit size:200, bit price:10.98
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::idx: 5, dt: 2020-01-06 12:18:45, bit size:109, bit price:10.98
2020-01-06 12:18:35:HMI-STK-SMART-USD:track::order bits done.
2020-01-06 12:18:40:HMI-STK-SMART-USD:track::notify_order: Limit Buy Completed, price: 10.986600660066006, size: 909, cost: 9986.82, comm: 4.545, ref: 6
2020-01-06 12:18:40:HMI-STK-SMART-USD:track::order bits: p1: 0, p2: 6
2020-01-06 12:18:40:HMI-STK-SMART-USD:track::idx: 0, dt: 2020-01-06 12:18:42, bit size:100, bit price:10.99
2020-01-06 12:18:40:HMI-STK-SMART-USD:track::idx: 1, dt: 2020-01-06 12:18:42, bit size:100, bit price:10.99
2020-01-06 12:18:40:HMI-STK-SMART-USD:track::idx: 2, dt: 2020-01-06 12:18:42, bit size:300, bit price:10.99
2020-01-06 12:18:40:HMI-STK-SMART-USD:track::idx: 3, dt: 2020-01-06 12:18:43, bit size:100, bit price:10.99
2020-01-06 12:18:40:HMI-STK-SMART-USD:track::idx: 4, dt: 2020-01-06 12:18:44, bit size:200, bit price:10.98
2020-01-06 12:18:40:HMI-STK-SMART-USD:track::idx: 5, dt: 2020-01-06 12:18:45, bit size:109, bit price:10.98
2020-01-06 12:18:40:HMI-STK-SMART-USD:track::order bits done.

The code that logs the order is:

    def log_order(self, order, prefix):
        order_data = order.executed if order.status in [Order.Completed, Order.Partial] else order.created
        self.log('{}: {} {} {}, price: {}, size: {}, cost: {}, comm: {}, ref: {}',
                 prefix,
                 order.getordername(),
                 order.ordtypename(),
                 order.getstatusname(),
                 order_data.price,
                 order_data.size,
                 order_data.value,
                 order_data.comm,
                 order.ref)
        self.log('order bits: p1: {}, p2: {}', order_data.p1, order_data.p2)
        for idx, bit in enumerate(order_data.exbits):
            if bit is None:
                break
            self.log('idx: {}, dt: {}, bit size:{}, bit price:{}', idx, order.data.num2date(bit.dt), bit.size, bit.price)
        self.log('order bits done.')

The above method is called from strategy's notify_order - very simple:

    def notify_order(self, order):
        self.log_order(order, "notify_order")

After taking a little bit deeper look inside the IBBroker's code and it seems that the p1 and p2 fields of the OrderData object are indeed not updated upon partial execution notifications.

I was looking at the following sequence of events:

IBStore.execDetails callback is called by IBpy
1.2. IBBroker.push_execution is called, pushing the notification message to IBBroker.executions map

IBStore.commissionReport callback is called by IBpy
2.1 IBBroker.push_commissionreport is called:
2.1.1 existing order is fetched from IBBroker.orderbyid map given commission report message m_execId
2.1.2 existing order's order.execute is called, which adds the execbits to the order.executed OrderData object
2.1.3 existing order id is added to the IBBroker.tonotify queue if it's not already there

Note: still the p1,p2 are not updated in the existing order in the above steps

IBStore.updatePortfolio is called by IBpy
3.1 IBBroker.push_portupdate is called
3.1.1 the order id is fetched from IBBroker.tonotify queue (updated in 2.1.3)
3.1.2 the order is fetched from IBBroker.orderbyid map for order id from the previous step
3.1.3 IBBroker.notify is called, eventually cloning the order and putting the clone into the IBBroker.notifs queue.

Note 1: Here in this step the p1, p2 fields of the cloned order are updated using markpending method:

def markpending(self):
        # rebuild the indices to mark which exbits are pending in clone
        self.p1, self.p2 = self.p2, len(self.exbits)

Note 2: p1 and p2 fields in the original order ( the one we were cloning from) are zero. So in the cloned order p1 will be zero and p2 will point to end of the exbits.

Note 3: The same sequence of events will be repeated for the next partial order notifications. In no place the original order's p1 and p2 fields are updated - so the same original order will be cloned once again (with zeroed p1 and p2 fields)

A simple fix maybe to call self.markpending() before cloning the OrderData:

def clone(self):
        self.markpending()  # <-- here
        obj = copy(self)
        return obj

It seems the 'fix' worked pretty well on real time (paper) trading.

2020-01-17 15:45:00:HMI-STK-SMART-USD:track:notify_order: Market Buy Partial, price: 14.63, size: 400, cost: 5852.0, comm: 2.0, ref: 7
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:order bits: p1: 0, p2: 3
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:idx: 0, dt: 2020-01-17 15:45:06, bit size:100, bit price:14.63
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:idx: 1, dt: 2020-01-17 15:45:06, bit size:200, bit price:14.63
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:idx: 2, dt: 2020-01-17 15:45:06, bit size:100, bit price:14.63
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:order bits done.
...
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:notify_order: Market Buy Partial, price: 14.63, size: 500, cost: 7315.0, comm: 2.5, ref: 7
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:order bits: p1: 3, p2: 4
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:idx: 0, dt: 2020-01-17 15:45:06, bit size:100, bit price:14.63
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:idx: 1, dt: 2020-01-17 15:45:06, bit size:200, bit price:14.63
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:idx: 2, dt: 2020-01-17 15:45:06, bit size:100, bit price:14.63
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:idx: 3, dt: 2020-01-17 15:45:08, bit size:100, bit price:14.63
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:idx: 4, dt: 2020-01-17 15:45:09, bit size:182, bit price:14.63
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:order bits done.
...
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:notify_order: Market Buy Completed, price: 14.629999999999999, size: 682, cost: 9977.66, comm: 3.41, ref: 7
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:order bits: p1: 4, p2: 5
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:idx: 0, dt: 2020-01-17 15:45:06, bit size:100, bit price:14.63
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:idx: 1, dt: 2020-01-17 15:45:06, bit size:200, bit price:14.63
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:idx: 2, dt: 2020-01-17 15:45:06, bit size:100, bit price:14.63
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:idx: 3, dt: 2020-01-17 15:45:08, bit size:100, bit price:14.63
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:idx: 4, dt: 2020-01-17 15:45:09, bit size:182, bit price:14.63
2020-01-17 15:45:00:HMI-STK-SMART-USD:track:order bits done.