Orders closing mysteriously in backtest...

[Slappy]

I should have added this information earlier. I am in Sydney (UTC+10).

I believe I may have recreated this issue using your code Chels. I modified it slightly to enter at 20:55 on the 27th June 2023 (my time at least) with a stop of 4679.75 I can get it to "fill" the stoploss even though the bar's Highs have not reached that price. The strange thing is that the execution log is coming in on the candle that makes sense at 12:00AM the next day. However this execution timestamp is occurring in between an 8:00PM and a 10:05PM log. Perhaps I am not understanding how the backtester is processing bars, but it seems like we are jumping back and forward through time in the backtest here. How could we fill an order on the 12:00AM primary bar but have yet to process the 10:05, 10:10, 10:15, etc. bars on the alternate data series?

Let me know what you make of the logs.

[NinjaTrader_ChelseaB]

Hello Slappy,

Yes, all of the processing for all orders of the bar happens at once using a fill algorithm, which can appear out of sequence.

From your output file the bar updates show the 10:00:00 bar closed before the order filled, which lets us know the order was still working after that bar had closed.

The execution shows us the time of the bar the order filled with.
28/06/2023 12:00:00 AM | execution='NT-00001-487' instrument='MES 12-24' account='Backtest' exchange=Default price=4679.75 quantity=1 marketPosition=Long orderId='NT-00001-487' time='2023-06-28 00:00:00' sod=False statementDate='0001-01-01'

This is why we suggest using an Exit order and submitting this to the correct bars in progress when submitting orders intra-bar, as the set methods cannot update with an added bar series.

https://support.ninjatrader.com/s/article/Developer-Guide-Improving-backtest-order-fill-accuracy-with-intrabar-granularity

[Slappy]

I think I understand what you are saying but it seems very counter intuitive...

When we print out the bar information each OBU call we see that the primary (120min) 10:00PM bar is processed, then the 10:00PM secondary (5min) bar, then suddenly the stop execution occurs with a timestamp of 12:00AM for the 120min series. This is then followed by the 10:05PM, 10:10PM, ... , 11:55PM 5min bars and THEN the 12:00AM 120min bar is updated.

I would have expected the execution to happen when we are processing the 12:00AM bar AFTER the 5min bars have been processed that make up that bar.

That said, I understand that the Set methods aren't written to handle this situation so I will have to rework my code to incorporate Exit methods.


27/06/2023 10:00:00 PM | BarsInProgress: 0, CurrentBars[0]: 18, Opens[0][0]: 4669.25, Highs[0]: 4673.25, Lows[0]: 4663.25, Closes[0]: 4665, BarsArray[0].GetCurrentAsk(18): 4669.75, BarsArray[0].GetCurrentBid(18): 4669.25
27/06/2023 10:00:00 PM | BarsInProgress: 3, CurrentBars[3]: 443, Opens[3][0]: 4664.75, Highs[3]: 4665.75, Lows[3]: 4663.75, Closes[3]: 4665, BarsArray[3].GetCurrentAsk(443): 4665.25, BarsArray[3].GetCurrentBid(443): 4664.75

27/06/2023 8:00:00 PM | orderId='NT-00001-487' account='Backtest' name='Stop loss' orderState=Filled instrument='MES 12-24' orderAction=BuyToCover orderType='Stop Market' limitPrice=0 stopPrice=4679.75 quantity=1 tif=Gtc oco='NT-00000-487' filled=1 averageFillPrice=4679.75 onBehalfOf='' id=-1 time='2023-06-27 20:00:00' gtd='2099-12-01' statementDate='2024-11-22'
28/06/2023 12:00:00 AM | execution='NT-00001-487' instrument='MES 12-24' account='Backtest' exchange=Default price=4679.75 quantity=1 marketPosition=Long orderId='NT-00001-487' time='2023-06-28 00:00:00' sod=False statementDate='0001-01-01'

27/06/2023 10:05:00 PM | BarsInProgress: 3, CurrentBars[3]: 444, Opens[3][0]: 4665, Highs[3]: 4665.75, Lows[3]: 4662.75, Closes[3]: 4664.5, BarsArray[3].GetCurrentAsk(444): 4665.5, BarsArray[3].GetCurrentBid(444): 4665
27/06/2023 10:10:00 PM | BarsInProgress: 3, CurrentBars[3]: 445, Opens[3][0]: 4664.75, Highs[3]: 4666.75, Lows[3]: 4664.25, Closes[3]: 4665.75, BarsArray[3].GetCurrentAsk(445): 4665.25, BarsArray[3].GetCurrentBid(445): 4664.75
27/06/2023 10:15:00 PM | BarsInProgress: 3, CurrentBars[3]: 446, Opens[3][0]: 4666, Highs[3]: 4666.75, Lows[3]: 4663.5, Closes[3]: 4664.5, BarsArray[3].GetCurrentAsk(446): 4666.5, BarsArray[3].GetCurrentBid(446): 4666
27/06/2023 10:20:00 PM | BarsInProgress: 3, CurrentBars[3]: 447, Opens[3][0]: 4664.5, Highs[3]: 4665.75, Lows[3]: 4663.75, Closes[3]: 4665.25, BarsArray[3].GetCurrentAsk(447): 4665, BarsArray[3].GetCurrentBid(447): 4664.5
27/06/2023 10:25:00 PM | BarsInProgress: 3, CurrentBars[3]: 448, Opens[3][0]: 4665.25, Highs[3]: 4665.25, Lows[3]: 4663.5, Closes[3]: 4664.75, BarsArray[3].GetCurrentAsk(448): 4665.75, BarsArray[3].GetCurrentBid(448): 4665.25
27/06/2023 10:30:00 PM | BarsInProgress: 3, CurrentBars[3]: 449, Opens[3][0]: 4664.5, Highs[3]: 4666, Lows[3]: 4664.25, Closes[3]: 4665.5, BarsArray[3].GetCurrentAsk(449): 4665, BarsArray[3].GetCurrentBid(449): 4664.5
27/06/2023 10:35:00 PM | BarsInProgress: 3, CurrentBars[3]: 450, Opens[3][0]: 4666, Highs[3]: 4669.25, Lows[3]: 4664.5, Closes[3]: 4669.25, BarsArray[3].GetCurrentAsk(450): 4666.5, BarsArray[3].GetCurrentBid(450): 4666
27/06/2023 10:40:00 PM | BarsInProgress: 3, CurrentBars[3]: 451, Opens[3][0]: 4669.25, Highs[3]: 4672.75, Lows[3]: 4668.25, Closes[3]: 4671.5, BarsArray[3].GetCurrentAsk(451): 4669.75, BarsArray[3].GetCurrentBid(451): 4669.25
27/06/2023 10:45:00 PM | BarsInProgress: 3, CurrentBars[3]: 452, Opens[3][0]: 4671.75, Highs[3]: 4672.75, Lows[3]: 4670.75, Closes[3]: 4671.75, BarsArray[3].GetCurrentAsk(452): 4672.25, BarsArray[3].GetCurrentBid(452): 4671.75
27/06/2023 10:50:00 PM | BarsInProgress: 3, CurrentBars[3]: 453, Opens[3][0]: 4671.75, Highs[3]: 4672.25, Lows[3]: 4669.75, Closes[3]: 4670.5, BarsArray[3].GetCurrentAsk(453): 4672.25, BarsArray[3].GetCurrentBid(453): 4671.75
27/06/2023 10:55:00 PM | BarsInProgress: 3, CurrentBars[3]: 454, Opens[3][0]: 4670.5, Highs[3]: 4670.5, Lows[3]: 4668.25, Closes[3]: 4668.75, BarsArray[3].GetCurrentAsk(454): 4671, BarsArray[3].GetCurrentBid(454): 4670.5
27/06/2023 11:00:00 PM | BarsInProgress: 3, CurrentBars[3]: 455, Opens[3][0]: 4668.75, Highs[3]: 4669.25, Lows[3]: 4667.5, Closes[3]: 4668.75, BarsArray[3].GetCurrentAsk(455): 4669.25, BarsArray[3].GetCurrentBid(455): 4668.75
27/06/2023 11:05:00 PM | BarsInProgress: 3, CurrentBars[3]: 456, Opens[3][0]: 4668.75, Highs[3]: 4669, Lows[3]: 4667, Closes[3]: 4668.25, BarsArray[3].GetCurrentAsk(456): 4669.25, BarsArray[3].GetCurrentBid(456): 4668.75
27/06/2023 11:10:00 PM | BarsInProgress: 3, CurrentBars[3]: 457, Opens[3][0]: 4668, Highs[3]: 4669.5, Lows[3]: 4667.25, Closes[3]: 4669.25, BarsArray[3].GetCurrentAsk(457): 4668.5, BarsArray[3].GetCurrentBid(457): 4668
27/06/2023 11:15:00 PM | BarsInProgress: 3, CurrentBars[3]: 458, Opens[3][0]: 4669.25, Highs[3]: 4671, Lows[3]: 4667.75, Closes[3]: 4670.5, BarsArray[3].GetCurrentAsk(458): 4669.75, BarsArray[3].GetCurrentBid(458): 4669.25
27/06/2023 11:20:00 PM | BarsInProgress: 3, CurrentBars[3]: 459, Opens[3][0]: 4670.75, Highs[3]: 4671.25, Lows[3]: 4669.5, Closes[3]: 4669.5, BarsArray[3].GetCurrentAsk(459): 4671.25, BarsArray[3].GetCurrentBid(459): 4670.75
27/06/2023 11:25:00 PM | BarsInProgress: 3, CurrentBars[3]: 460, Opens[3][0]: 4669.5, Highs[3]: 4670.25, Lows[3]: 4669.25, Closes[3]: 4669.75, BarsArray[3].GetCurrentAsk(460): 4670, BarsArray[3].GetCurrentBid(460): 4669.5
27/06/2023 11:30:00 PM | BarsInProgress: 3, CurrentBars[3]: 461, Opens[3][0]: 4669.5, Highs[3]: 4671.75, Lows[3]: 4669.5, Closes[3]: 4670.75, BarsArray[3].GetCurrentAsk(461): 4670, BarsArray[3].GetCurrentBid(461): 4669.5
27/06/2023 11:35:00 PM | BarsInProgress: 3, CurrentBars[3]: 462, Opens[3][0]: 4670.75, Highs[3]: 4675.25, Lows[3]: 4669, Closes[3]: 4674.25, BarsArray[3].GetCurrentAsk(462): 4671.25, BarsArray[3].GetCurrentBid(462): 4670.75
27/06/2023 11:40:00 PM | BarsInProgress: 3, CurrentBars[3]: 463, Opens[3][0]: 4674.25, Highs[3]: 4680.5, Lows[3]: 4674.25, Closes[3]: 4677.5, BarsArray[3].GetCurrentAsk(463): 4674.75, BarsArray[3].GetCurrentBid(463): 4674.25
27/06/2023 11:45:00 PM | BarsInProgress: 3, CurrentBars[3]: 464, Opens[3][0]: 4677.5, Highs[3]: 4679.25, Lows[3]: 4675.75, Closes[3]: 4676.75, BarsArray[3].GetCurrentAsk(464): 4678, BarsArray[3].GetCurrentBid(464): 4677.5
27/06/2023 11:50:00 PM | BarsInProgress: 3, CurrentBars[3]: 465, Opens[3][0]: 4676.75, Highs[3]: 4677.75, Lows[3]: 4669.5, Closes[3]: 4672.75, BarsArray[3].GetCurrentAsk(465): 4677.25, BarsArray[3].GetCurrentBid(465): 4676.75
27/06/2023 11:55:00 PM | BarsInProgress: 3, CurrentBars[3]: 466, Opens[3][0]: 4672.5, Highs[3]: 4676.75, Lows[3]: 4671.5, Closes[3]: 4674, BarsArray[3].GetCurrentAsk(466): 4673, BarsArray[3].GetCurrentBid(466): 4672.5

28/06/2023 12:00:00 AM | BarsInProgress: 0, CurrentBars[0]: 19, Opens[0][0]: 4665, Highs[0]: 4680.5, Lows[0]: 4662.75, Closes[0]: 4674.75, BarsArray[0].GetCurrentAsk(19): 4665.5, BarsArray[0].GetCurrentBid(19): 4665