MarketOrder() would start trading right away, the args would be ignored.

Here's an example of what happens with StopOrder ...

Buy on 3-05  
Starts selling on 3-06 when the stop of 271.50 is hit.  
Continues selling even though price rises above the stop price.  
So the stop order became a market order as expected.

2018-03-06 07:56 handle_data:28 INFO 271.98         100  
2018-03-06 07:57 handle_data:28 INFO 272.04         100  
2018-03-06 07:58 handle_data:28 INFO 271.49         97  
2018-03-06 07:59 handle_data:28 INFO 271.57         96  
2018-03-06 08:00 handle_data:28 INFO 271.65         95  
2018-03-06 08:01 handle_data:28 INFO 271.56         94  
2018-03-06 08:02 handle_data:28 INFO 271.82         93  

Try https://www.quantopian.com/posts/track-orders in your backtest, it should help.

@Blue

I was trying to figure out the issue with this algo here: https://www.quantopian.com/posts/nice-n-steady-low-vol-high-dividend-with-a-vol-kicker
Slippage is set to 0, yet keep getting orders failed to fill by end of day, when I played around and switched things to MarketOrder those fill issues seemed to go away.

Maybe you can take a look and see what's going on.

Thanks

@Blue

Implemented your code thanks, here are the logs still having a hard time understanding what is going on, maybe I need to call it in more places?

2011-11-01 09:31  PRINT Optimization terminated successfully.  
2011-11-01 09:31  PRINT          Current function value: -1482.039362  
2011-11-01 09:31  PRINT          Iterations: 63  
2011-11-01 09:31  PRINT          Function evaluations: 123  
2011-11-01 09:31 update_indices_HISTORY:906 INFO ratio:1.00628930818 days=-11, vix=33.39, vxv=33.6  
2011-11-01 09:31 update_indices_HISTORY:906 INFO ratio:1.01330798479 days=-10, vix=31.56, vxv=31.98  
2011-11-01 09:31 update_indices_HISTORY:906 INFO ratio:0.998548199768 days=-9, vix=34.44, vxv=34.39  
2011-11-01 09:31 update_indices_HISTORY:906 INFO ratio:0.983323749281 days=-8, vix=34.78, vxv=34.2  
2011-11-01 09:31 update_indices_HISTORY:906 INFO ratio:1.02075351213 days=-7, vix=31.32, vxv=31.97  
2011-11-01 09:31 update_indices_HISTORY:906 INFO ratio:1.04135338346 days=-6, vix=29.26, vxv=30.47  
2011-11-01 09:31 update_indices_HISTORY:906 INFO ratio:1.00434512725 days=-5, vix=32.22, vxv=32.36  
2011-11-01 09:31 update_indices_HISTORY:906 INFO ratio:1.03616878768 days=-4, vix=29.86, vxv=30.94  
2011-11-01 09:31 update_indices_HISTORY:906 INFO ratio:1.06166535742 days=-3, vix=25.46, vxv=27.03  
2011-11-01 09:31 update_indices_HISTORY:906 INFO ratio:1.08112515287 days=-2, vix=24.53, vxv=26.52  
2011-11-01 09:31 log_factors:617 INFO zscore=-1.02951112036, yesterday=1.08112515287, today=1.01368491322, breadth=0.004, spy_current=121.56, spy_yest_high=127.26, WVF[-1]=33.9896281972, WVF[-2]=36.8198997978, WVF[-3]=nan, RSI_signal=0, rsi7_actual=34.9567100736, rsi2_actual=9.02585322608, proj_vix_d=-0.150598085328, file_vix=29.96, cboe_VIX=29.96, cboe_VVIX=104.84, cboe_VIX_ma3=97.8233333333, file_vxv=30.37, VXV_Close=30.37  
2011-11-01 09:40  PRINT Optimization terminated successfully.  
2011-11-01 09:40  PRINT          Current function value: -1482.039362  
2011-11-01 09:40  PRINT          Iterations: 63  
2011-11-01 09:40  PRINT          Function evaluations: 123  
2011-11-01 09:40 factors:550 INFO zscore=-1.02951112036, today=1.01368491322, yesterday=1.08112515287, days_ago_2=1.06166535742, days_ago_3=1.03616878768, days_ago_4=1.00434512725, breadth=0.012, spy_current=122.09, spy_yest_high=127.26, WVF[-1]=33.9896281972, WVF[-2]=36.8198997978, XIV_Change=-0.106430868167, RSI_signal=0, rsi7_actual=35.038176783, rsi2_actual=9.07201575163, proj_vix_d=-0.150598085328, cboe_VIX=29.96, cboe_VVIX=104.84, cboe_VIX_ma3=97.8233333333  
2011-11-01 09:40 rebalance_vol_vts:707 INFO Ordering: VXX amount: 0.817440239656  
2011-11-01 09:40 rebalance_vol_vts:707 INFO Ordering: XIV amount: 0.0  
2011-11-01 09:41 _trac:1019 INFO   11   Sell -529 VXX (529) at 46.19 stop 44.44          ecf4  
2011-11-01 10:15 _trac:1019 INFO   45   Buy 22 CPB _ at 32.92                            70bf  
2011-11-01 10:15 _trac:1019 INFO   45   Buy 10 KMB _ at 68.91                            2585  
2011-11-01 10:15 _trac:1019 INFO   45   Buy 32 KR _ at 22.86                             f1b1  
2011-11-01 10:15 _trac:1019 INFO   45   Buy 8 BCR _ at 84.51                             970d  
2011-11-01 10:15 _trac:1019 INFO   45   Buy 29 CAG _ at 25.08                            f1e1  
2011-11-01 10:15 _trac:1019 INFO   45   Buy 11 LLL _ at 66.17                            da16  
2011-11-01 10:15 _trac:1019 INFO   45   Buy 9 LMT _ at 74.39                             7d27  
2011-11-01 10:15 WARN Logging limit exceeded; some messages discarded  
2011-11-01 16:00 WARN Your order for -22 shares of CPB failed to fill by the end of day and was canceled.  
2011-11-01 16:00 WARN Your order for -10 shares of KMB failed to fill by the end of day and was canceled.  
2011-11-01 16:00 WARN Your order for -32 shares of KR failed to fill by the end of day and was canceled.  
2011-11-01 16:00 WARN Your order for -8 shares of BCR failed to fill by the end of day and was canceled.  
2011-11-01 16:00 WARN Your order for -29 shares of CAG failed to fill by the end of day and was canceled.  
2011-11-01 16:00 WARN Your order for -9 shares of LMT failed to fill by the end of day and was canceled.  
2011-11-01 16:00 WARN Your order for -6 shares of LO failed to fill by the end of day and was canceled.  
2011-11-01 16:00 WARN Your order for -9 shares of BDX failed to fill by the end of day and was canceled.  
2011-11-02 09:31  PRINT Optimization terminated successfully.  
2011-11-02 09:31  PRINT          Current function value: -1483.168959  
2011-11-02 09:31  PRINT          Iterations: 61  
2011-11-02 09:31  PRINT          Function evaluations: 119  
2011-11-02 09:31 log_factors:617 INFO zscore=-1.46978624878, yesterday=1.01368491322, today=0.978429680759, breadth=0.892, spy_current=123.92, spy_yest_high=123.51, WVF[-1]=22.1938999736, WVF[-2]=33.9896281972, WVF[-3]=nan, RSI_signal=0, rsi7_actual=40.6777805586, rsi2_actual=30.8394523766, proj_vix_d=-0.237175330167, file_vix=34.77, cboe_VIX=34.77, cboe_VVIX=113.15, cboe_VIX_ma3=104.06, file_vxv=34.02, VXV_Close=34.02  
2011-11-02 09:36 _trac:1019 INFO    6     Canceled Sell -8 BCR stop 82.85 at 84.72     9dfc  
2011-11-02 09:36 _trac:1019 INFO    6     Canceled Sell -32 KR stop 22.25 at 22.82     8cc3  
2011-11-02 09:36 _trac:1019 INFO    6     Canceled Sell -6 LO stop 106.65 at 108.77     f966  
2011-11-02 09:36 _trac:1019 INFO    6     Canceled Sell -9 LMT stop 73.15 at 74.89     1f94  
2011-11-02 09:36 _trac:1019 INFO    6     Canceled Sell -10 KMB stop 67.15 at 69.25     59cf  
2011-11-02 09:36 _trac:1019 INFO    6     Canceled Sell -9 BDX stop 75.35 at 71.01     6d40  
2011-11-02 09:36 _trac:1019 INFO    6     Canceled Sell -29 CAG stop 24.35 at 25.415     c7d8  
2011-11-02 09:36 _trac:1019 INFO    6     Canceled Sell -22 CPB stop 32.05 at 32.93     1791  
2011-11-02 09:36 _trac:1019 INFO    6   Sell -22 CPB (22) at 32.93 stop 32.25            9b31  
2011-11-02 09:36 _trac:1019 INFO    6   Sell -10 KMB (10) at 69.25 stop 67.55            e512  
2011-11-02 09:36 _trac:1019 INFO    6   Sell -32 KR (32) at 22.82 stop 22.35             2326  
2011-11-02 09:36 _trac:1019 INFO    6   Sell -8 BCR (8) at 84.72 stop 82.75              b183  
2011-11-02 09:36 _trac:1019 INFO    6   Sell -29 CAG (29) at 25.41 stop 24.55            c467  
2011-11-02 09:36 _trac:1019 INFO    6   Sell -9 LMT (9) at 74.89 stop 72.85              ecd7  
2011-11-02 09:36 _trac:1019 INFO    6   Sell -6 LO (6) at 108.77 stop 105.85             8490  
2011-11-02 09:36 _trac:1019 INFO    6   Sell -9 BDX (9) at 71.01 stop 74.55              6673  
2011-11-02 09:40  PRINT Optimization terminated successfully.  
2011-11-02 09:40  PRINT          Current function value: -1483.168959  
2011-11-02 09:40  PRINT          Iterations: 61  
2011-11-02 09:40  PRINT          Function evaluations: 119  
2011-11-02 09:40 factors:550 INFO zscore=-1.46978624878, today=0.978429680759, yesterday=1.01368491322, days_ago_2=1.08112515287, days_ago_3=1.06166535742, days_ago_4=1.03616878768, breadth=0.928, spy_current=123.61, spy_yest_high=123.51, WVF[-1]=22.1938999736, WVF[-2]=33.9896281972, XIV_Change=-0.105426356589, RSI_signal=0, rsi7_actual=39.1124090809, rsi2_actual=24.729819749, proj_vix_d=-0.237175330167, cboe_VIX=34.77, cboe_VVIX=113.15, cboe_VIX_ma3=104.06  
2011-11-02 09:40 WARN Logging limit exceeded; some messages discarded  
2011-11-02 16:00 WARN Your order for -22 shares of CPB failed to fill by the end of day and was canceled.  
2011-11-02 16:00 WARN Your order for -3763 shares of XIV failed to fill by the end of day and was canceled.  
2011-11-02 16:00 WARN Your order for -10 shares of KMB failed to fill by the end of day and was canceled.  
2011-11-02 16:00 WARN Your order for -32 shares of KR failed to fill by the end of day and was canceled.  
2011-11-02 16:00 WARN Your order for -8 shares of BCR failed to fill by the end of day and was canceled.  
2011-11-02 16:00 WARN Your order for -29 shares of CAG failed to fill by the end of day and was canceled.  
2011-11-02 16:00 WARN Your order for -10 shares of CLX failed to fill by the end of day and was canceled.  
2011-11-02 16:00 WARN Your order for -10 shares of LLL failed to fill by the end of day and was canceled.  
2011-11-02 16:00 WARN Your order for -9 shares of LMT failed to fill by the end of day and was canceled.  
2011-11-02 16:00 WARN Your order for -16 shares of RTN failed to fill by the end of day and was canceled.  
2011-11-02 16:00 WARN Your order for -6 shares of LO failed to fill by the end of day and was canceled.  
2011-11-03 09:31  PRINT Optimization terminated successfully.  
2011-11-03 09:31  PRINT          Current function value: -1478.768980  
2011-11-03 09:31  PRINT          Iterations: 61  
2011-11-03 09:31  PRINT          Function evaluations: 120  
2011-11-03 09:31 log_factors:617 INFO zscore=-1.13879432141, yesterday=0.978429680759, today=1.00427611484, breadth=0.866, spy_current=125.2, spy_yest_high=124.4, WVF[-1]=22.6158038147, WVF[-2]=22.1938999736, WVF[-3]=nan, RSI_signal=0, rsi7_actual=43.3918986934, rsi2_actual=47.3063317979, proj_vix_d=-0.281051222273, file_vix=32.74, cboe_VIX=32.74, cboe_VVIX=107.4, cboe_VIX_ma3=108.463333333, file_vxv=32.88, VXV_Close=32.88  
2011-11-03 09:36 _trac:1019 INFO    6     Canceled Sell -3763 XIV stop 5.53 at 5.881     e789  
2011-11-03 09:36 _trac:1019 INFO    6     Canceled Sell -6 LO stop 105.85 at 110.38     8490  
2011-11-03 09:36 _trac:1019 INFO    6     Canceled Sell -22 CPB stop 32.25 at 32.9     9b31  
2011-11-03 09:36 _trac:1019 INFO    6     Canceled Sell -10 KMB stop 67.55 at 69.48     e512  
2011-11-03 09:36 _trac:1019 INFO    6     Canceled Sell -8 BCR stop 82.75 at 86.79     b183  
2011-11-03 09:36 _trac:1019 INFO    6     Canceled Sell -10 LLL stop 63.75 at 67.46     7cd6  
2011-11-03 09:36 _trac:1019 INFO    6     Canceled Sell -10 CLX stop 63.45 at 65.27     fad6  
2011-11-03 09:36 _trac:1019 INFO    6     Canceled Sell -29 CAG stop 24.55 at 25.302     c467  
2011-11-03 09:36 _trac:1019 INFO    6     Canceled Sell -32 KR stop 22.35 at 22.57     2326  
2011-11-03 09:36 _trac:1019 INFO    6     Canceled Sell -9 LMT stop 72.85 at 75.18     ecd7  
2011-11-03 09:36 _trac:1019 INFO    6     Canceled Sell -16 RTN stop 41.65 at 43.95     40a4  

Thanks for doing that. You might have it right, the key thing is that the schedule_function for track_orders has to be listed last after others. It needs to see when every new order has just been opened in that minute, to store the order id. If there's something tricky in this code you're right you might have to call it in some other places too. That's quite the backtest, nearly a thousand lines of code.

There's an issue with overwhelming the logging window and a couple of things that can help.

• Turn off any other logging that can be considered non-essential.
  
• Make existing log messages brief because the window limit operates on number of characters (in tandem also with number of lines I think).
  (I removed my word 'cash' for this reason).
  
• If you find any of this tool's options not really useful you can turn them off for fewer characters logged.
  
• If you have a specific date to look at, you can enter a day or two before that (or that day) in 'start' : []. Can be started, stopped multiple times.
  
• Here, I added the ability to filter for one or more symbols in a list (and updated the track_orders page).
  
• At some point the logging of canceled orders could become less interesting, I added an option to turn those off, making room in logging.

I took the liberty of turning some of this backtest's logging off and that generated more warnings, so you know.
The first column is minute of the day.

This is an order to sell 32 long shares of KR currently at 22.82 using a stop price of 22.35. In parens, current number of shares.
Sell -32 KR (32) at 22.82 stop 22.35
The stop was not reached so this happened at the end of the day:
2011-11-02 16:00 WARN Your order for -32 shares of KR failed to fill by the end of day and was canceled.
Currently I have those turned off because I forgot to turn them back on. If you want to see them, comment out the scheduling of cncl_oos which is the other thing I also added to this backtest.
When a stop is hit, you'll see the word 'Sold'. Buys filled say 'Bot' for brevity.
Partial fills will be visible.
An underscore is my replacement for 0, just easier to spot.
You can highlight the logging window contents to copy to an external editor, it will pick up lots of other stuff on the page, I have a macro that removes them. For me, 4 page-downs in the logging window and it will be a perfect continuation, thank you Q, I don't know about other screens out there.
I'm on Windows and like Notepad++ for an external editor. In that I can highlight an order id or symbol and the other instances are highlighted as well. Useful.

Here's a suitably representative output with two buy orders that are filled and the stop orders for them are placed.
Those are happening in the same minute though, so it is assumed they will fill? Careful with that, if there are partial fills. Would wind up short.
Another route is to wait until the next minute for what was actually filled. I have some code that updates stop (and limit) orders as partials happen. It was difficult to pull off. I don't use the stops, limits part anymore because I'm using order_optimal_portfolio where other order types are a no-op. It is integrated with a bunch of other tools and took so much time & effort with far more info and tailorable, I'd love to share it with the community but would need a philanthropist to motivate me (where a lot to me is just a little bit to them). Just flipping a 0 to 1 for example and stops, limits were activated and improved all of the lecture series backtests rather dramatically.

2011-02-01 07:15 _trac:1036 INFO   45   Buy 73 CPB _ at 34.26                                 3171  8181  
2011-02-01 07:15 _trac:1036 INFO   45   Sell -33 ETR (33) at 72.56                            3171  2218  
2011-02-01 07:15 _trac:1036 INFO   45   Buy 32 CL _ at 76.95                                  3171  6c08  
2011-02-01 07:16 _trac:1036 INFO   46      Sold -33 ETR _ at 72.55                            599  2218  
2011-02-01 07:16 _trac:1036 INFO   46      Bot 32 CL (32) at 76.93                            599  6c08  
2011-02-01 07:16 _trac:1036 INFO   46      Bot 73 CPB (73) at 34.26                           599  8181  
2011-02-01 07:16 _trac:1036 INFO   46   Sell -73 CPB (73) at 34.26 stop 33.0                  599  579e  
2011-02-01 07:16 _trac:1036 INFO   46   Sell -32 CL (32) at 76.93 stop 74.15                  599  52a3  

This is where a stop order closed the position:

47      Sold -77 CPB _ at 33.37 stop 33.65                 2878  8b78

Just running the first six months here and didn't notice any partial fills, just stops not hit all day.

This is from your link above, https://www.quantopian.com/posts/nice-n-steady-low-vol-high-dividend-with-a-vol-kicker
The algo over there isn't in the realm of the contest or fund, I'd be curious what route people intend for making use of it.
All that talent, could go toward the fund.

Contrary to my comment above nearly a year ago ...
It appears order_optimal_portfolio (required in the contest) no longer fills in the same minute when it runs in IDE backtesting as of at least Feb 2019 unless there are certain conditions where Optimize still does so.