Lost an execution with IB this morning...

[heech]

Hi,

I "lost" an execution this morning. (Didn't receive a call to OnExecution.)

6/24/2009 7:08:23 AM|1|32|Order='1db44957d54e40998e42737a0af2e43a/' Name='MexitCSIQ|13|0' New State=PendingSubmit Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Type=Market Filled=0 Fill price=0 Error=NoError Native error=''
6/24/2009 7:08:23 AM|2|4|Order Event Warning:Attribute 'Outside Regular Trading Hours' is ignored based on the order type and destination. PlaceOrder is now being processed. 2109
6/24/2009 7:08:23 AM|1|32|Order='1775127453/' Name='MexitCSIQ|13|0' New State=Accepted Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Type=Market Filled=0 Fill price=0 Error=NoError Native error=''
6/24/2009 7:08:23 AM|1|32|Order='1775127453/' Name='MexitCSIQ|13|0' New State=Working Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Type=Market Filled=0 Fill price=0 Error=NoError Native error=''
6/24/2009 7:08:23 AM|1|32|Order='1775127453/' Name='MexitCSIQ|13|0' New State=PartFilled Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Type=Market Filled=100 Fill price=12.3 Error=NoError Native error=''
6/24/2009 7:08:23 AM|1|16|Execution='CSIQ/0000d81a.4a421ae5.01.01' Instrument='CSIQ' Account='' Exchange=Default Price=12.3 Quantity=100 Market position=Long Operation=Insert Order='1775127453' Time='6/24/2009 7:08:23 AM'
6/24/2009 7:08:26 AM|1|32|Order='1775127453/' Name='MexitCSIQ|13|0' New State=PartFilled Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Type=Market Filled=1000 Fill price=12.3 Error=NoError Native error=''
6/24/2009 7:08:26 AM|1|32|Order='1775127453/' Name='MexitCSIQ|13|0' New State=PartFilled Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Type=Market Filled=1500 Fill price=12.3 Error=NoError Native error=''
6/24/2009 7:08:26 AM|1|16|Execution='CSIQ/0001142e.4a422ae3.01.01' Instrument='CSIQ' Account='' Exchange=Ise Price=12.3 Quantity=500 Market position=Long Operation=Insert Order='1775127453' Time='6/24/2009 7:08:26 AM'
6/24/2009 7:08:26 AM|1|16|Execution='CSIQ/00012c7d.4a41f383.01.01' Instrument='CSIQ' Account='' Exchange=Arca Price=12.31 Quantity=100 Market position=Long Operation=Insert Order='1775127453' Time='6/24/2009 7:08:26 AM'
6/24/2009 7:08:26 AM|1|32|Order='1775127453/' Name='MexitCSIQ|13|0' New State=Filled Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Type=Market Filled=1600 Fill price=12.3006 Error=NoError Native error=''
6/24/2009 7:08:26 AM|1|64|Instrument='CSIQ' Account='' Avg price=11.90991085 Quantity=3,200 Market position=Short Operation=Update Currency=UsDollar
6/24/2009 7:08:26 AM|0|128|Unable to match order state to execution: Order='1775127453/' Name='MexitCSIQ|13|0' State=Filled Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Strategy='ProtectDownMulti' Type=Market Tif=Gtc Oco='' Filled=1600 Fill price=12.3006 Token='004e9d2ec1014825ae4b39bb460d551f' Gtd='12/1/2099 12:00:00 AM' / Execution='CSIQ/0001142e.4a422ae3.01.01' Instrument='CSIQ' Account='' Name='MexitCSIQ|13|0' Exchange=Ise Price=12.3 Quantity=500 Market position=Long Commission=0 Order='1775127453' Time='6/24/2009 7:08:26 AM'
6/24/2009 7:08:26 AM|0|128|Unable to match order state to execution: Order='1775127453/' Name='MexitCSIQ|13|0' State=Filled Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Strategy='ProtectDownMulti' Type=Market Tif=Gtc Oco='' Filled=1600 Fill price=12.3006 Token='004e9d2ec1014825ae4b39bb460d551f' Gtd='12/1/2099 12:00:00 AM' / Execution='CSIQ/00012c7d.4a41f383.01.01' Instrument='CSIQ' Account='' Name='MexitCSIQ|13|0' Exchange=Arca Price=12.31 Quantity=100 Market position=Long Commission=0 Order='1775127453' Time='6/24/2009 7:08:26 AM'

If you look at the section that's in bold above...

- I received OnOrderUpdate with PartFilled event, showing Filled = 100.
- I received OnExecution for those 100 shares. (So far so good)
- I received OnOrderUpdate with PartFilled, showing Filled = 1000

I did *not* receive OnExecution for the 900 shares that took me to 1000 shares. I've confirmed in TWS that there was indeed a 900 share execution. I also don't see the 900 share execution in my "executions" tab.

I only noticed this about an hour later, when I realized there was a discrepancy between my strategy + account positions.

I am using OnExecution to track actual fills, because I've been told before that with IB (and other brokers as well), OnOrderUpdate had some latent bugs that meant we couldn't trust it fully. OnExecution, as far as I knew, was perfect up until this point.

Note that about 15 seconds after this above order, I placed/filled two more orders for CSIQ (1600 shares each), and both of those worked fine.

[NinjaTrader_Jason]

Hello heech,

I noticed the following message in the log:

6/24/2009 7:08:26 AM|0|128|Unable to match order state to execution: Order='1775127453/' Name='MexitCSIQ|13|0' State=Filled Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Strategy='ProtectDownMulti' Type=Market Tif=Gtc Oco='' Filled=1600 Fill price=12.3006 Token='004e9d2ec1014825ae4b39bb460d551f' Gtd='12/1/2099 12:00:00 AM' / Execution='CSIQ/0001142e.4a422ae3.01.01' Instrument='CSIQ' Account='' Name='MexitCSIQ|13|0' Exchange=Ise Price=12.3 Quantity=500 Market position=Long Commission=0 Order='1775127453' Time='6/24/2009 7:08:26 AM'

I suggest to restart NinjaTrader and TWS and check if you receive the execution upon re-connection to IB.

In addition, you can always add manual executions using the Executions-tab in the Control Center. More information can be found at the link below.

http://www.ninjatrader-support.com/HelpGuideV6/ExecutionsTab.html

[heech]

Here's the same time frame from the trace file. Nothing in there indicates an error:

2009-06-24 07:08:23:360 (xIB556) IB.Adapter.Submit: Id=55 Order='1db44957d54e40998e42737a0af2e43a/' Name='MexitCSIQ|13|0' State=Initialized Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Strategy='ProtectDownMulti' Type=Market Tif=Gtc Oco='' Filled=0 Fill price=0 Token='004e9d2ec1014825ae4b39bb460d551f' Gtd='12/1/2099 12:00:00 AM'
2009-06-24 07:08:23:407 (xIB556) IB.OrderRequest.Send: tmOrderId='1db44957d54e40998e42737a0af2e43a' orderId ='55' instrument='CSIQ' expiry='' strikePrice=0 right='' exchange='SMART' action='BUY' limitPrice=0 auxPrice=0 quantity=1600 type='MKT' tif='GTC' oca=''
2009-06-24 07:08:23:407 (xIB556) Cbi.Connection.ProcessEventArgs.OrderStatusEventAr gs: Order='1db44957d54e40998e42737a0af2e43a/' Name='MexitCSIQ|13|0' New State=PendingSubmit Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Type=Market Filled=0 Fill price=0 Error=NoError Native error=''
2009-06-24 07:08:23:407 (xIB556) Cbi.Order.Update1: oldid='1db44957d54e40998e42737a0af2e43a' Order='1db44957d54e40998e42737a0af2e43a/' Name='MexitCSIQ|13|0' New State=PendingSubmit Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Type=Market Filled=0 Fill price=0 Error=NoError Native error=''
2009-06-24 07:08:23:407 (xIB556) Cbi.OrderStatusEventArgs.Process: Order='1db44957d54e40998e42737a0af2e43a/' Name='MexitCSIQ|13|0' New State=Initialized Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Type=Market Filled=0 Fill price=0 Error=NoError Native error=''
2009-06-24 07:08:23:423 (xIB556) Cbi.OrderStatusEventArgs.Process: Order='1db44957d54e40998e42737a0af2e43a/' Name='MexitCSIQ|13|0' New State=PendingSubmit Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Type=Market Filled=0 Fill price=0 Error=NoError Native error=''
2009-06-24 07:08:23:423 WARNING: Order Event Warning:Attribute 'Outside Regular Trading Hours' is ignored based on the order type and destination. PlaceOrder is now being processed. 2109
2009-06-24 07:08:23:720 (xIB556) IB.ExecutionsRequest.Process: id='0000d81a.4a421ae5.01.01' instrument='CSIQ' expiry='12/1/2099 12:00:00 AM' sectype='STK' orderid='1775127453' account='' filled=100 price=12.3 side='BOT' permId='1775127453' liquidation=0
2009-06-24 07:08:23:720 (xIB556) IB.OrderRequest.ProcessOpenOrders: id='1775127453' orderId=55 quantity=1600 lmtPrice=0 auxprice=0 account=''
2009-06-24 07:08:23:720 (xIB556) IB.OrderRequest.Process: id='1775127453' state='PendingSubmit' filled=100 price=12.3 / Order='1db44957d54e40998e42737a0af2e43a/' Name='MexitCSIQ|13|0' State=PendingSubmit Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Strategy='ProtectDownMulti' Type=Market Tif=Gtc Oco='' Filled=0 Fill price=0 Token='004e9d2ec1014825ae4b39bb460d551f' Gtd='12/1/2099 12:00:00 AM'
2009-06-24 07:08:23:720 (xIB556) IB.ExecutionsRequest.ProcessNow.PostponeExecution: Execution='CSIQ/0000d81a.4a421ae5.01.01' Instrument='CSIQ' Account='' Exchange=Default Price=12.3 Quantity=100 Market position=Long Operation=Insert Order='1775127453' Time='6/24/2009 7:08:23 AM'
2009-06-24 07:08:23:720 (xIB556) IB.OrderRequest.ProcessOpenOrders: id='1775127453' orderId=55 quantity=1600 lmtPrice=0 auxprice=0 account=''
2009-06-24 07:08:23:720 (xIB556) IB.OrderRequest.Process: id='1775127453' state='Submitted' filled=100 price=12.3 / Order='1db44957d54e40998e42737a0af2e43a/' Name='MexitCSIQ|13|0' State=PendingSubmit Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Strategy='ProtectDownMulti' Type=Market Tif=Gtc Oco='' Filled=0 Fill price=0 Token='004e9d2ec1014825ae4b39bb460d551f' Gtd='12/1/2099 12:00:00 AM'
2009-06-24 07:08:23:720 (xIB556) IB.ExecutionsRequest.Process: id='0001142e.4a422ae2.01.01' instrument='CSIQ' expiry='12/1/2099 12:00:00 AM' sectype='STK' orderid='1775127453' account='' filled=900 price=12.3 side='BOT' permId='1775127453' liquidation=0
2009-06-24 07:08:23:720 (xIB556) IB.OrderRequest.ProcessOpenOrders: id='1775127453' orderId=55 quantity=1600 lmtPrice=0 auxprice=0 account=''
2009-06-24 07:08:23:720 (xIB556) IB.OrderRequest.Process: id='1775127453' state='Submitted' filled=1000 price=12.3 / Order='1db44957d54e40998e42737a0af2e43a/' Name='MexitCSIQ|13|0' State=PendingSubmit Instrument='CSIQ' Action=BuyToCover Limit price=0 Stop price=0 Quantity=1,600 Strategy='ProtectDownMulti' Type=Market Tif=Gtc Oco='' Filled=0 Fill price=0 Token='004e9d2ec1014825ae4b39bb460d551f' Gtd='12/1/2099 12:00:00 AM'
2009-06-24 07:08:23:720 (xIB556) IB.ExecutionsRequest.Process: id='0001142e.4a422ae3.01.01' instrument='CSIQ' expiry='12/1/2099 12:00:00 AM' sectype='STK' orderid='1775127453' account='' filled=500 price=12.3 side='BOT' permId='1775127453' liquidation=0

[heech]

Hello heech,

I noticed the following message in the log:

6/24/2009 7:08:26 AM|0|128|Unable to match order state to execution: ...

Jason,

That's an incredibly, incredibly common message with anyone using IB. There's a long-standing, known bug with the way Ninja matches part-fills to execution. I probably get that message 20 times a day... you can check with Dierk. It should have nothing to do with this new bug.

I don't really care about the missing execution, in terms of manually injecting it. But my strategy depends on accurate calls to OnExecution() for every order fill, and not getting it is a real problem.

[NinjaTrader_Jason]

Could you please send me your entire log and trace files to support[at]ninjatrader[dot]com. Please reference this thread and put 'Attn Jason' in the subject header.

Did re-connecting make any difference?

[heech]

Could you please send me your entire log and trace files to support[at]ninjatrader[dot]com. Please reference this thread and put 'Attn Jason' in the subject header.

Did re-connecting make any difference?

Sure, I tried to submit the log through the Help menu, but it crashed NT. I'll zip up today's log and trace files and send it over.

[NinjaTrader_Ray]

Heech,

- This is already addressed for NT7
- Race condition that can occur if you place an order on exchange A but get filled on exchange B, C, D etc...
- We believe you ran into that before which is what resulted in a fix for NT7
- We believe a workaround for 6.5 would be to add the instrument + all potential exchanges that you could receive a fill to ANY instrument list in the Instrument Manager

[heech]

Heech,

- This is already addressed for NT7
- Race condition that can occur if you place an order on exchange A but get filled on exchange B, C, D etc...
- We believe you ran into that before which is what resulted in a fix for NT7
- We believe a workaround for 6.5 would be to add the instrument + all potential exchanges that you could receive a fill to ANY instrument list in the Instrument Manager

Ray,

Hmm, I definitely haven't run into this before.

There was a problem before where a database transaction (setting up a new instrument Ninja hadn't seen before) would take too long to execute, sometimes cause an execution to be lost... but there would be an error message in that case, related to the database transaction. But in this case, it has nothing to do with database access.

No one ever told me there was an actual behind-the-scenes bug that's been addressed in NT7! If you're certain that's the case, great, I'll patiently wait. I execute enough trades to know that this isn't terribly common (first time in 6 months, and about 1500 trades)... I think I can wait a few months.