Alpaca Close order missing

[pwidden]

Whilst testing paper trading on Apaca, I noticed that there's a mismatch between what QR thinks is the case and what Alpaca thinks.

QR entered the market at ~3:30:
quantrocket blotter status
1c0b112a-abd7-496d-b6ec-d96ee5727b6c,alpaca,FIBBG000BDTBL9,SELL,33,PA23J54L7CWT,first-last-live,2020-06-26T19:30:06+00:00,Filled,33,0,null

At 3:45 I submitted the MOC close order:
quantrocket blotter close --order-refs 'first-last-live' --params 'OrderType:MKT' 'Tif:MOC' | quantrocket blotter order -f '-'

quantrocketec2_houston_1|172.18.0.15 - - [26/Jun/2020:19:45:03 +0000] "DELETE /blotter/positions.csv?order_refs=first-last-live&params=OrderType%3AMKT&params=Tif%3AMOC HTTP/1.1" 200 5 "-" "-"
quantrocketec2_houston_1|172.18.0.15 - - [26/Jun/2020:19:45:03 +0000] "POST /blotter/orders HTTP/1.1" 200 3 "-" "-"

But this order doesn't show up in the blotter status and my positions are empty:

quantrocket blotter positions

However my Alpaca account still shows the 33 short.

[Brian]

When you run

$ quantrocket blotter close --order-refs ‘first-last-live’ --params ‘OrderType:MKT’ ‘Tif:MOC’ | quantrocket blotter order -f ‘-’

it will return the order ID, if an order was placed. You can then use the order ID to check the status:

quantrocket blotter status --order-ids <order id>

I would start there. The houston output you posted doesn't actually prove an order was placed, just that those commands were run.

I see you're using a custom project name quantrocketec2. Make sure you're closing the position on the same deployment as the one where you placed the original order. That’s one scenario I can think of that would explain the sequence of events you saw.

[pwidden]

Thanks for the response Brian.

Running:

quantrocket blotter close --order-refs ‘first-last-live’

Shows no results at all.

I only have one installation, so I'm sure it was executed on the correct one.

[Brian]

Everything suggests the order was opened and closed, and the only anomaly is the position you see in Alpaca. Any chance you opened the short position twice, then closed it once?

I'm not sure what else to suggest other than to try working through order placement fresh from start to finish.

[pwidden]

@pwidden

first-last-live

Here's the entire order list of the first-last-live strategy:

quantrocket blotter status |grep first-last-live

de63dce8-9df3-4af9-9c8e-9a5d7701ed0f,alpaca,FIBBG000BDTBL9,BUY,32,PA23J54L7CWT,first-last-live,2020-06-19T19:30:04+00:00,Filled,32,0,null

1c862714b28811ea9fab0242ac120011,alpaca,FIBBG000BDTBL9,SELL,32,PA23J54L7CWT,first-last-live,2020-06-19T23:53:45+00:00,Error,0,32,"[{""ErrorCode"": 40010001, ""ErrorMsg"": ""invalid order type""}]"

2b53b22ab28811ea9fab0242ac120011,alpaca,FIBBG000BDTBL9,SELL,32,PA23J54L7CWT,first-last-live,2020-06-19T23:54:10+00:00,Error,0,32,"[{""ErrorCode"": 40010001, ""ErrorMsg"": ""invalid order type""}]"

63c10bcd-f60a-42fa-b25c-e3452413b530,alpaca,FIBBG000BDTBL9,SELL,32,PA23J54L7CWT,first-last-live,2020-06-19T23:57:24+00:00,Cancelled,0,32,null

d9c4d935-08a3-4eef-92fa-7a73d5460130,alpaca,FIBBG000BDTBL9,SELL,32,PA23J54L7CWT,first-last-live,2020-06-22T16:16:48+00:00,Filled,32,0,null

1c0b112a-abd7-496d-b6ec-d96ee5727b6c,alpaca,FIBBG000BDTBL9,SELL,33,PA23J54L7CWT,first-last-live,2020-06-26T19:30:06+00:00,Filled,33,0,null

f986b299-237f-4725-a967-0a5c9152d236,alpaca,FIBBG000BDTBL9,BUY,32,PA23J54L7CWT,first-last-live,2020-06-30T19:30:07+00:00,Filled,32,0,null

e041207c-442e-454d-ad97-39105064a23a,alpaca,FIBBG000BDTBL9,SELL,32,PA23J54L7CWT,first-last-live,2020-06-30T19:45:03+00:00,Filled,32,0,null

2edf6342-7c6d-4a48-b177-d5d88481cc76,alpaca,FIBBG000BDTBL9,BUY,32,PA23J54L7CWT,first-last-live,2020-07-01T19:30:06+00:00,Filled,32,0,null

79d3f5fe-b065-42db-bb91-636b3496323e,alpaca,FIBBG000BDTBL9,SELL,32,PA23J54L7CWT,first-last-live,2020-07-01T19:45:02+00:00,Filled,32,0,null

I would have expected to see a buy 33 on the 26th given the logs above.

[Brian]

If you query the executions for the strategy (quantrocket blotter executions) does it line up with the order statuses?

quantrocket blotter close looks at the LatestPosition table (same as quantrocket blotter positions). The LatestPosition table is updated based on the incoming execution records from Alpaca.

[pwidden]

@pwidden

quantrocket blotter status |grep first-last-live

I don't see the 33 short:

quantrocket blotter executions|grep first-last-live

20200619033004845::183cb24a-5057-4445-b13c-6ed04bb8f16c,de63dce8-9df3-4af9-9c8e-9a5d7701ed0f,PA23J54L7CWT,first-last-live,FIBBG000BDTBL9,2020-06-19T19:30:04,,309.94,BOT,32,0,,,,SPY,USD,STK,1,1,99877.12,USD,1,-9918.08,-9918.08,-9918.08,0.0

20200622121648232::530d4499-85c7-4c66-8e59-dd21185976b3,d9c4d935-08a3-4eef-92fa-7a73d5460130,PA23J54L7CWT,first-last-live,FIBBG000BDTBL9,2020-06-22T16:16:48,,310.34,SLD,-32,0,,,,SPY,USD,STK,1,1,100012.8,USD,1,9930.88,9930.88,9930.88,0.0

20200630033007467::cee17355-023e-48ee-b33e-cdfecd440bda,f986b299-237f-4725-a967-0a5c9152d236,PA23J54L7CWT,first-last-live,FIBBG000BDTBL9,2020-06-30T19:30:07,,307.69,BOT,32,0,,,,SPY,USD,STK,1,1,99655.93,USD,1,-9846.08,-9846.08,-9846.08,0.0

20200630035957246::35d9efa8-dd41-44ac-9ef5-71ded17efc9a,e041207c-442e-454d-ad97-39105064a23a,PA23J54L7CWT,first-last-live,FIBBG000BDTBL9,2020-06-30T19:59:57,,309.45,SLD,-32,0,,,,SPY,USD,STK,1,1,99655.93,USD,1,9902.4,9902.4,9902.4,0.0

20200701033007060::1759ff4f-ad21-4476-9639-5fb98d33480f,2edf6342-7c6d-4a48-b177-d5d88481cc76,PA23J54L7CWT,first-last-live,FIBBG000BDTBL9,2020-07-01T19:30:07,,311.54,BOT,32,0,,,,SPY,USD,STK,1,1,99547.09,USD,1,-9969.28,-9969.28,-9969.28,0.0

20200701035957624::cde76dbd-2196-49ea-ad16-b49e2effc913,79d3f5fe-b065-42db-bb91-636b3496323e,PA23J54L7CWT,first-last-live,FIBBG000BDTBL9,2020-07-01T19:59:57,,310.49,SLD,-32,0,,,,SPY,USD,STK,1,1,99547.09,USD,1,9935.68,9935.68,9935.68,0.0

[Brian]

Since there is no execution record for the SELL 33, when you tried to close the position, QuantRocket thought there was no position and did nothing.

So the question is why was there no execution record for the SELL 33? On the 26th QuantRocket would have been expected to make an API call like the one below to get the latest Alpaca executions.

import alpaca_trade_api as tradeapi
api = tradeapi.REST(api_key, secret_key, base_url="https://paper-api.alpaca.markets", api_version='v2')

# this is the latest execution QR knew about on the 26th
latest_execution_id = "20200622121648232::530d4499-85c7-4c66-8e59-dd21185976b3"

executions = api.get_activities(
        activity_types=["FILL"], direction="asc",
        page_size=100, page_token=latest_execution_id)

QuantRocket would then look at the order_id field in the returned executions and match the executions to any orders it knows about. Please run this in a notebook or console and see if you find an execution with order_id 1c0b112a-abd7-496d-b6ec-d96ee5727b6c

[pwidden]

Looks like there are two:
AccountActivity({ 'activity_type': 'FILL', 'cum_qty': '12', 'id': '20200626033006626::4aa6dcd2-d16b-46c6-aae3-882743bf5085', 'leaves_qty': '21', 'order_id': '1c0b112a-abd7-496d-b6ec-d96ee5727b6c', 'price': '300.35', 'qty': '12', 'side': 'sell_short', 'symbol': 'SPY', 'transaction_time': '2020-06-26T19:30:06.626249Z', 'type': 'partial_fill'}),
AccountActivity({ 'activity_type': 'FILL', 'cum_qty': '33', 'id': '20200626033007109::5e020a37-dfcc-4bf3-96b5-90788e30e8e7', 'leaves_qty': '0', 'order_id': '1c0b112a-abd7-496d-b6ec-d96ee5727b6c', 'price': '300.33', 'qty': '21', 'side': 'sell_short', 'symbol': 'SPY', 'transaction_time': '2020-06-26T19:30:07.109777Z', 'type': 'fill'}),

[Brian]

Would you mind sending your logs to brian at quantrocket dot com?

quantrocket flightlog get app.log
quantrocket flightlog get -d sys.log
gzip app.log
gzip sys.log

[Brian]

I think there are two next steps here.

One, since the logs had rotated out, it would be nice to catch this issue as it's happening. Among other things, that would help rule out the possibility that Alpaca was delayed in returning that execution. Running this command on the crontab during the period you hold positions will log to flightlog if the blotter and Alpaca disagree about your positions (it could be combined with a Papertrail alert).

quantrocket blotter positions -a <ACCOUNT> --broker --diff | quantrocket flightlog log --level CRITICAL

If that alerts you to a repeat of the issue, a nice first step would be to promptly manually query the Alpaca executions like above and see if the execution is present.

The second next step is that I think the blotter should request a more generous overlap of executions from Alpaca, instead of using the last_execution_id. What if there was some kind of race condition where execution B arrived and got saved before execution A, then execution A was no longer requested because the blotter thought it was up-to-date through B? That could be prevented by always requesting all executions that are later than, say, an hour ago. There's no downside to doing that, so it seems prudent. Whether a race condition is likely to explain your issue might depend on whether you had other Alpaca executions (from any source, not just QuantRocket) that were close in time to the missed execution. Was that the case?

[Brian]

QuantRocket 2.1.0 is now available and includes new behavior to request an overlap of executions from Alpaca.

QuantRocket 2.1.0 Release Notes

QuantRocket 2.1.0 is now available. This release contains a number of enhancements and usability improvements for Zipline strategy development, as well as bug fixes. All version 2 users are encouraged to update to the latest version. See how to update. Highlights This release introduces a new Zipline Research API which greatly improves usability by allowing you to perform much of your Zipline strategy development within the interactive environment of a research notebook. It includes support f…