Possible BUG in Metatrader backtest (order expire but order state is still the same)

New comment
 

Hi,

I wrote a linear grid EA that generally works fine except on some testing scenarios. At some point in time, some orders will expire multiple times and others won't expire at all, and the status of the orders will still be like if they were open. See below for more details.

Does anyone knows how to solve this problem or if it is indeed a platform bug?


BUILD:

Using build 2962, although noticed the problem on 2960. Cannot tell if older versions have the same behavior.


DETAILS:

Testing from 2020.02.17 to 2021.06.01 on Brazilian ticker WIN$N, the EA works fine until 2020.11.24:

QK      0       11:04:32.151    LinearGridEA (WIN$N,D1) 2020.11.23 18:24:59   [DEBUG | LinearGrid.mqh | bool CLinearGrid::UpdateProcessOrders() | line: 739] Total number of pending orders: 4
HQ      0       11:04:32.151    LinearGridEA (WIN$N,D1) 2020.11.23 18:24:59   #ticket 2037 ORDER_TYPE_BUY_LIMIT 1 WIN$N at 104000 was set up at 2020.11.23 09:00
FG      0       11:04:32.151    LinearGridEA (WIN$N,D1) 2020.11.23 18:24:59   #ticket 2038 ORDER_TYPE_BUY_LIMIT 1 WIN$N at 105000 was set up at 2020.11.23 09:00
KE      0       11:04:32.151    LinearGridEA (WIN$N,D1) 2020.11.23 18:24:59   #ticket 2040 ORDER_TYPE_SELL_LIMIT 1 WIN$N at 108500 was set up at 2020.11.23 09:00
RD      0       11:04:32.151    LinearGridEA (WIN$N,D1) 2020.11.23 18:24:59   #ticket 2041 ORDER_TYPE_BUY_LIMIT 1 WIN$N at 106000 was set up at 2020.11.23 13:00
KN      0       11:04:32.151    LinearGridEA (WIN$N,D1) 2020.11.23 18:24:59   
KI      0       11:04:32.151    LinearGridEA (WIN$N,D1) 2020.11.23 18:24:59   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(COrderInfo&,double,double) | line: 260] Set Order Info: Symbol=WIN$N, Ticket=2037, Type=ORDER_TYPE_BUY_LIMIT, State=ORDER_STATE_PLACED, Time=2020.11.23 09:00:00, Price Open=104000, Price Current=107455, Price Limit=0, Vol Ini=1, Vol Cur=1
IM      0       11:04:32.151    LinearGridEA (WIN$N,D1) 2020.11.23 18:24:59   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(COrderInfo&,double,double) | line: 260] Set Order Info: Symbol=WIN$N, Ticket=2038, Type=ORDER_TYPE_BUY_LIMIT, State=ORDER_STATE_PLACED, Time=2020.11.23 09:00:00, Price Open=105000, Price Current=107455, Price Limit=0, Vol Ini=1, Vol Cur=1
QO      0       11:04:32.151    LinearGridEA (WIN$N,D1) 2020.11.23 18:24:59   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(COrderInfo&,double,double) | line: 260] Set Order Info: Symbol=WIN$N, Ticket=2040, Type=ORDER_TYPE_SELL_LIMIT, State=ORDER_STATE_PLACED, Time=2020.11.23 09:00:40, Price Open=108500, Price Current=107450, Price Limit=0, Vol Ini=1, Vol Cur=1
IE      0       11:04:32.151    LinearGridEA (WIN$N,D1) 2020.11.23 18:24:59   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(COrderInfo&,double,double) | line: 260] Set Order Info: Symbol=WIN$N, Ticket=2041, Type=ORDER_TYPE_BUY_LIMIT, State=ORDER_STATE_PLACED, Time=2020.11.23 13:00:40, Price Open=106000, Price Current=107455, Price Limit=0, Vol Ini=1, Vol Cur=1

OP      0       11:04:32.152    Trade   2020.11.24 09:00:00   order expired [#2037 buy limit 1 WIN$N at 104000]
PD      0       11:04:32.153    Trade   2020.11.24 09:00:00   order expired [#2038 buy limit 1 WIN$N at 105000]
CG      0       11:04:32.153    Trade   2020.11.24 09:00:00   order expired [#2040 sell limit 1 WIN$N at 108500]
RR      0       11:04:32.153    Trade   2020.11.24 09:00:00   order expired [#2041 buy limit 1 WIN$N at 106000]

OI      0       11:04:32.158    LinearGridEA (WIN$N,D1) 2020.11.24 09:00:00   [DEBUG | LinearGrid.mqh | bool CLinearGrid::UpdateProcessOrders() | line: 739] Total number of pending orders: 0
KP      0       11:04:32.158    LinearGridEA (WIN$N,D1) 2020.11.24 09:00:00   
RH      0       11:04:32.166    LinearGridEA (WIN$N,D1) 2020.11.24 09:00:00   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(CHistoryOrderInfo&,double,double) | line: 181] Set History Order Info: Symbol=WIN$N, Ticket=2037, Type=ORDER_TYPE_BUY_LIMIT, State=ORDER_STATE_EXPIRED, Time=2020.11.23 09:00:00, Price Open=104000, Price Current=108120, Price Limit=0, Vol Ini=1, Vol Cur=0
IF      0       11:04:32.170    LinearGridEA (WIN$N,D1) 2020.11.24 09:00:00   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(CHistoryOrderInfo&,double,double) | line: 181] Set History Order Info: Symbol=WIN$N, Ticket=2038, Type=ORDER_TYPE_BUY_LIMIT, State=ORDER_STATE_EXPIRED, Time=2020.11.23 09:00:00, Price Open=105000, Price Current=108120, Price Limit=0, Vol Ini=1, Vol Cur=0
RG      0       11:04:32.171    LinearGridEA (WIN$N,D1) 2020.11.24 09:00:00   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(CHistoryOrderInfo&,double,double) | line: 181] Set History Order Info: Symbol=WIN$N, Ticket=2040, Type=ORDER_TYPE_SELL_LIMIT, State=ORDER_STATE_EXPIRED, Time=2020.11.23 09:00:40, Price Open=108500, Price Current=108115, Price Limit=0, Vol Ini=1, Vol Cur=0
CO      0       11:04:32.171    LinearGridEA (WIN$N,D1) 2020.11.24 09:00:00   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(CHistoryOrderInfo&,double,double) | line: 181] Set History Order Info: Symbol=WIN$N, Ticket=2041, Type=ORDER_TYPE_BUY_LIMIT, State=ORDER_STATE_EXPIRED, Time=2020.11.23 13:00:40, Price Open=106000, Price Current=108120, Price Limit=0, Vol Ini=1, Vol Cur=0

Until 2020.11.24, all orders expire at the end of each day, and the EA is able to get the updated state (ORDER_STATE_EXPIRED) from each order.

But on 2020.11.25 the problem happens:

LI      0       11:04:33.804    LinearGridEA (WIN$N,D1) 2020.11.24 18:24:59   [DEBUG | LinearGrid.mqh | bool CLinearGrid::UpdateProcessOrders() | line: 739] Total number of pending orders: 6
KL      0       11:04:33.804    LinearGridEA (WIN$N,D1) 2020.11.24 18:24:59   #ticket 2047 ORDER_TYPE_BUY_LIMIT 1 WIN$N at 107000 was set up at 2020.11.24 11:22
LO      0       11:04:33.804    LinearGridEA (WIN$N,D1) 2020.11.24 18:24:59   #ticket 2048 ORDER_TYPE_BUY_STOP 1 WIN$N at 111000 was set up at 2020.11.24 12:21
FF      0       11:04:33.804    LinearGridEA (WIN$N,D1) 2020.11.24 18:24:59   #ticket 2049 ORDER_TYPE_SELL_LIMIT 1 WIN$N at 110500 was set up at 2020.11.24 12:21
CJ      0       11:04:33.804    LinearGridEA (WIN$N,D1) 2020.11.24 18:24:59   #ticket 2050 ORDER_TYPE_BUY_LIMIT 1 WIN$N at 108000 was set up at 2020.11.24 13:52
DJ      0       11:04:33.804    LinearGridEA (WIN$N,D1) 2020.11.24 18:24:59   #ticket 2051 ORDER_TYPE_BUY_STOP 1 WIN$N at 112000 was set up at 2020.11.24 17:54
JN      0       11:04:33.804    LinearGridEA (WIN$N,D1) 2020.11.24 18:24:59   #ticket 2052 ORDER_TYPE_SELL_LIMIT 1 WIN$N at 111500 was set up at 2020.11.24 17:54
FS      0       11:04:33.804    LinearGridEA (WIN$N,D1) 2020.11.24 18:24:59   
QF      0       11:04:33.804    LinearGridEA (WIN$N,D1) 2020.11.24 18:24:59   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(COrderInfo&,double,double) | line: 260] Set Order Info: Symbol=WIN$N, Ticket=2047, Type=ORDER_TYPE_BUY_LIMIT, State=ORDER_STATE_PLACED, Time=2020.11.24 11:22:40, Price Open=107000, Price Current=110195, Price Limit=0, Vol Ini=1, Vol Cur=1
RM      0       11:04:33.804    LinearGridEA (WIN$N,D1) 2020.11.24 18:24:59   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(COrderInfo&,double,double) | line: 260] Set Order Info: Symbol=WIN$N, Ticket=2048, Type=ORDER_TYPE_BUY_STOP, State=ORDER_STATE_PLACED, Time=2020.11.24 12:21:40, Price Open=111000, Price Current=110190, Price Limit=0, Vol Ini=1, Vol Cur=1
MP      0       11:04:33.804    LinearGridEA (WIN$N,D1) 2020.11.24 18:24:59   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(COrderInfo&,double,double) | line: 260] Set Order Info: Symbol=WIN$N, Ticket=2049, Type=ORDER_TYPE_SELL_LIMIT, State=ORDER_STATE_PLACED, Time=2020.11.24 12:21:40, Price Open=110500, Price Current=110190, Price Limit=0, Vol Ini=1, Vol Cur=1
EJ      0       11:04:33.804    LinearGridEA (WIN$N,D1) 2020.11.24 18:24:59   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(COrderInfo&,double,double) | line: 260] Set Order Info: Symbol=WIN$N, Ticket=2050, Type=ORDER_TYPE_BUY_LIMIT, State=ORDER_STATE_PLACED, Time=2020.11.24 13:52:40, Price Open=108000, Price Current=110195, Price Limit=0, Vol Ini=1, Vol Cur=1
FI      0       11:04:33.804    LinearGridEA (WIN$N,D1) 2020.11.24 18:24:59   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(COrderInfo&,double,double) | line: 260] Set Order Info: Symbol=WIN$N, Ticket=2051, Type=ORDER_TYPE_BUY_STOP, State=ORDER_STATE_PLACED, Time=2020.11.24 17:54:40, Price Open=112000, Price Current=110190, Price Limit=0, Vol Ini=1, Vol Cur=1
IL      0       11:04:33.804    LinearGridEA (WIN$N,D1) 2020.11.24 18:24:59   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(COrderInfo&,double,double) | line: 260] Set Order Info: Symbol=WIN$N, Ticket=2052, Type=ORDER_TYPE_SELL_LIMIT, State=ORDER_STATE_PLACED, Time=2020.11.24 17:54:40, Price Open=111500, Price Current=110190, Price Limit=0, Vol Ini=1, Vol Cur=1

JS      0       11:04:33.805    Trade   2020.11.25 09:00:00   order expired [#2047 buy limit 1 WIN$N at 107000]
OE      0       11:04:33.805    Trade   2020.11.25 09:00:00   order expired [#2048 buy stop 1 WIN$N at 111000]
GD      0       11:04:33.805    Trade   2020.11.25 09:00:00   order expired [#2049 sell limit 1 WIN$N at 110500]
FP      0       11:04:33.805    Trade   2020.11.25 09:00:00   order expired [#2052 sell limit 1 WIN$N at 111500]
JL      0       11:04:33.805    Trade   2020.11.25 09:00:00   order expired [#2052 sell limit 1 WIN$N at 111500]
NI      0       11:04:33.805    Trade   2020.11.25 09:00:00   order expired [#2052 sell limit 1 WIN$N at 111500]

DN      0       11:35:11.579    LinearGridEA (WIN$N,D1) 2020.11.25 09:00:00   [DEBUG | LinearGrid.mqh | bool CLinearGrid::UpdateProcessOrders() | line: 739] Total number of pending orders: 2
OF      0       11:35:11.579    LinearGridEA (WIN$N,D1) 2020.11.25 09:00:00   #ticket 2050 ORDER_TYPE_BUY_LIMIT 1 WIN$N at 108000 was set up at 2020.11.24 13:52
PJ      0       11:35:11.579    LinearGridEA (WIN$N,D1) 2020.11.25 09:00:00   #ticket 2051 ORDER_TYPE_BUY_STOP 1 WIN$N at 112000 was set up at 2020.11.24 17:54
QI      0       11:35:11.579    LinearGridEA (WIN$N,D1) 2020.11.25 09:00:00   
JO      0       11:35:11.593    LinearGridEA (WIN$N,D1) 2020.11.25 09:00:00   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(CHistoryOrderInfo&,double,double) | line: 181] Set History Order Info: Symbol=WIN$N, Ticket=2047, Type=ORDER_TYPE_BUY_LIMIT, State=ORDER_STATE_EXPIRED, Time=2020.11.24 11:22:40, Price Open=107000, Price Current=109555, Price Limit=0, Vol Ini=1, Vol Cur=0
CR      0       11:35:11.593    LinearGridEA (WIN$N,D1) 2020.11.25 09:00:00   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(CHistoryOrderInfo&,double,double) | line: 181] Set History Order Info: Symbol=WIN$N, Ticket=2048, Type=ORDER_TYPE_BUY_STOP, State=ORDER_STATE_EXPIRED, Time=2020.11.24 12:21:40, Price Open=111000, Price Current=109550, Price Limit=0, Vol Ini=1, Vol Cur=0
EL      0       11:35:11.607    LinearGridEA (WIN$N,D1) 2020.11.25 09:00:00   [ERROR | ModelOrderList.mqh | bool CModelOrderList::UpdateOrders() | line: 244] Unable to set order object for ticket #2049
CH      0       11:35:11.609    LinearGridEA (WIN$N,D1) 2020.11.25 09:00:00   [ERROR | ModelOrderList.mqh | bool CModelOrderList::UpdateOrders() | line: 249] Ticket has some internal problem, not related to object
HP      0       11:35:11.609    LinearGridEA (WIN$N,D1) 2020.11.25 09:00:00   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(COrderInfo&,double,double) | line: 260] Set Order Info: Symbol=WIN$N, Ticket=2050, Type=ORDER_TYPE_BUY_LIMIT, State=ORDER_STATE_PLACED, Time=2020.11.24 13:52:40, Price Open=108000, Price Current=109555, Price Limit=0, Vol Ini=1, Vol Cur=1
GK      0       11:35:11.609    LinearGridEA (WIN$N,D1) 2020.11.25 09:00:00   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(COrderInfo&,double,double) | line: 260] Set Order Info: Symbol=WIN$N, Ticket=2051, Type=ORDER_TYPE_BUY_STOP, State=ORDER_STATE_PLACED, Time=2020.11.24 17:54:40, Price Open=112000, Price Current=109550, Price Limit=0, Vol Ini=1, Vol Cur=1
NJ      0       11:35:11.609    LinearGridEA (WIN$N,D1) 2020.11.25 09:00:00   [DEBUG | ModelOrder.mqh | bool CModelOrder::Set(CHistoryOrderInfo&,double,double) | line: 181] Set History Order Info: Symbol=WIN$N, Ticket=2052, Type=ORDER_TYPE_SELL_LIMIT, State=ORDER_STATE_PLACED, Time=2020.11.24 17:54:40, Price Open=111500, Price Current=109550, Price Limit=0, Vol Ini=1, Vol Cur=0

The first strange behavior I noticed is that, although the number of orders to be expired match, order #2052 repeated 3 times, while others were not expired. Next, when trying to fetch the order #2049 information, it fails for both HistoryOrderSelect and OrderSelect. And although HistoryOrderSelect worked on order #2052, the state was still ORDER_STATE_PLACED. Next day, the orders start to expire normally again until the end of the testing.

Below are the details of the orders that failed:

ID      SYMBOL  TIME_SETUP      TYPE    STATE   TYPE_FILLING    EXPIRATION      TIME_DONE       MAGIC           POSITION_ID     PRICE_OPEN      PRICE_CURRENT   PRICE_STOPLIMIT STOP_LOSS       TAKE_PROFIT     VOLUME_INITIAL  VOLUME_CURRENT
2049    WIN$N   1606220500      3       1       2               1606176000      0               2147278848      0               110500          0               0               0                0              1               1
2052    WIN$N   1606240480      3       1       2               1606176000      0               2147278848      0               111500          0               0               0                0              1               1

I attached the list of deals that happened on the test. If I start the test on  2020.02.24, no error happens.

For completeness here is the snipped of code to create the buy/sell orders (for Buystop and SellLimit, the code is the same):

   CTrade trade;
   trade.SetDeviationInPoints(m_deviation);
   trade.SetExpertMagicNumber(m_magic);
   trade.SetTypeFilling(ORDER_FILLING_RETURN);

   if(!trade.BuyLimit(volume, NormalizeDouble(price, m_digits), m_symbol, 0.0, 0.0, ORDER_TIME_DAY, 0, comment))
     {
      PrintFormat("Failed to do a BuyLimit: RetCode: %d, Code Description: %s", trade.ResultRetcode(), trade.ResultRetcodeDescription());
      return false;
     }
Files:
Deals.csv  83 kb
 

Do you want to be a beta-tester ?

Last official release if 2940.

You reported a coding issue without posting any useful code.

 
Alain Verleyen:

Do you want to be a beta-tester ?

Last official release if 2940.

You reported a coding issue without posting any useful code.


Hi Alain,


Apologize for the delay. Updated my MT5 with latest beta and the error seems to be gone. Will continue testing and will update this thread if find any new problems. Thank you for the help.

New comment