Inconsistency Between Expert and Journal Log

New comment
 

Greetings All!

I am trying to get to the bottom of an incredibly strange issue, where my experts log and journal log are not matching up. The primary problem is that i am seeing two trades taken in the journal, but only 1 in the experts log, which from looking at the code is impossible.

Please see key part of experts log below:


12:10:51 TC EURUSD,H1: Trade: 11740585 received by client

12:10:51 TC EURUSD,H1: Order on GBPUSD received. Trading 0.30000000 lots at 1.59261000

12:10:52 TC EURUSD,H1: open #33447961 buy 0.30 GBPUSD at 1.59261 ok

12:10:52 TC EURUSD,H1: Order 33447961 filled successfully

12:10:54 TC EURUSD,H1: Trade: 11740590 received by client

12:10:55 TC EURUSD,H1: Order on GBPUSD received. Trading 0.30000000 lots at 1.59260000

12:10:56 TC EURUSD,H1: open #33448090 buy 0.30 GBPUSD at 1.59260 ok

12:10:56 TC EURUSD,H1: Order 33448090 filled successfully

This clearly shows that two trades were received, and two were opened, one at 12:10:52, the other at 12:10:56

now if we look at the journal below, we see this:

12:10:51 'xxx': instant order buy 0.30 GBPUSD at 1.59261 sl: 0.00000 tp: 0.00000

12:10:51 'xxx': request was accepted by server

12:10:51 'xxx': request in process

12:10:52 'xxx': order was opened : #33447961 buy 0.30 GBPUSD at 1.59261 sl: 0.00000 tp: 0.00000

12:10:52 'xxx': instant order buy 0.30 GBPUSD at 1.59261 sl: 0.00000 tp: 0.00000

12:10:52 'xxx': request was accepted by server

12:10:52 'xxx': request in process

12:10:53 'xxx': order was opened : #33448026 buy 0.30 GBPUSD at 1.59261 sl: 0.00000 tp: 0.00000

12:10:55 'xxx': instant order buy 0.30 GBPUSD at 1.59260 sl: 0.00000 tp: 0.00000

12:10:55 'xxx': request was accepted by server

12:10:55 'xxx': request in process

12:10:56 'xxx': order was opened : #33448090 buy 0.30 GBPUSD at 1.59260 sl: 0.00000 tp: 0.00000

We now have 3 trades, one at 12:10:52, 12:10:53, and 12:10:56

the one that is missing from the experts log is 12:10:53 which you will notice there is a complete gap in the experts log for.

we know 100% that there would have had to be a trade received log entry in it, as otherwise it would not have the information it requires to place the trade.

Here is the method for opening the trade:

void OpenTrade(  int PortfolioID,
                  int MasterTradeID,
                  string SymbolID,
                  int OrderTypeID,
                  double OpenPrice,
                  double Slippage,
                  double StopLoss,
                  int MoneyManagementID,
                  double Lots,
                  double Risk,
                  double PercentToMirror,
                  double Size,
                  double MasterRisk,
                  double MaxLots,
                  int WorkID,
                  int ServiceLinkID)
 {
 if (PortfolioID > 0 && MasterTradeID > 0)
 {
   string tradeComment = "TC:" + MasterTradeID; // get the trade ID

   Log("Trade: " + MasterTradeID + " received by client", 5, MasterTradeID);
   
   // order is already open, update and skip.
   if(AlreadyOpen(MasterTradeID,ServiceLinkID,WorkID))
      return;
              
   if(!MarketInfo(SymbolID,MODE_TRADEALLOWED))
   {                  
      Log("Instrument not supported, skipping order", 3, MasterTradeID);
      OpenUpdateOrder(0, WorkID, MasterTradeID, 1, -2, ServiceLinkID);
      return;
   }
   
   RefreshRates();
   double Price = 0;
   if(OrderTypeID == 0)
      Price = MarketInfo(SymbolID, MODE_ASK);
   else
      Price = MarketInfo(SymbolID, MODE_BID);
      
   double pip = 0.0001;
   if(MarketInfo(SymbolID, MODE_DIGITS) < 4)
      pip = 0.01;
      
   if(MathAbs(OpenPrice - Price) >= Slippage * pip && Slippage > 0)
   {
       Log("Order on " + SymbolID + " received, but price slippage too high. Waiting. Master Price " + OpenPrice + " Slave Price " + Price, 5, MasterTradeID);
       return;   
   }
   
   double TradeLots = GetRisk(Price, StopLoss, MasterTradeID, MoneyManagementID, Lots, Risk, SymbolID, MasterRisk, PercentToMirror, Size, MaxLots);
   if(TradeLots == 0)
   {
      Log("MM Calculation Failed", 3, MasterTradeID);
      return;
   }
   
   Log("Order on " + SymbolID + " received. Trading " + TradeLots + " lots at " + Price, 1, MasterTradeID);
   
   int ExecutedOrder;
   
   if(OrderTypeID == 0)
      ExecutedOrder = OrderSend(SymbolID, OP_BUY, TradeLots, Price, 100, 0, 0, tradeComment, 1985, 0);
   else
      ExecutedOrder = OrderSend(SymbolID, OP_SELL, TradeLots, Price, 100, 0, 0, tradeComment, 1985, 0);
   
   if(ExecutedOrder > 0)
   {
      Log("Order " + ExecutedOrder + " filled successfully", 5, MasterTradeID);
      OpenUpdateOrder(ExecutedOrder, WorkID, MasterTradeID, 1, 1, ServiceLinkID);
      UpdateClientOrder(ExecutedOrder);
   }
   else
      Log("Order open failed: " + ErrorDescription(GetLastError()), 3, MasterTradeID);   
   
  } 
}

As you can see its impossible to hit OrderSend without going through a number of log functions. The code for the Log function is here: 

bool Log(string Message, int LogType, int MasterTradeID)
{
   string params [0,2];
  
   ArrayResize( params, 0); // Flush old data
   int status[1];           // HTTP Status code
        
   addParam("ACTION","LOG",params);
   addParam("ACCOUNTID",AccountID,params);
   addParam("MASTERTRADEID",MasterTradeID,params);
   addParam("LOGTYPE",LogType,params);
   addParam("LOGMESSAGE",Message,params);   
  
   Print(Message);
   string req = ArrayEncode(params);
   
   string res = httpPOST("http://xxxxxxxx", req, status);
            
   return(true);
 }

As you can see we do use an external function to write the log to a database, but there is a simple Print before that.

I have seen strange issues in the past where a DLL that is not built correctly can cause buffer overruns that effects the print functions of an EA, at this stage this is the only assumption i can make. what is more weird about this is that this code has been stable and running on hundreds of platforms for nearly 3 months, its only in the past week or so we have noticed this issue.

Any ideas?

 
GreatSamps:

Greetings All!

I am trying to get to the bottom of an incredibly strange issue, where my experts log and journal log are not matching up. The primary problem is that i am seeing two trades taken in the journal, but only 1 in the experts log, which from looking at the code is impossible.

Please see key part of experts log below:



the one that is missing from the experts log is 12:10:53 which you will notice there is a complete gap in the experts log for.


Any ideas?

Are you copy and pasting from the experts tab or from the log file ?
 
RaptorUK:
Are you copy and pasting from the experts tab or from the log file ?


Hi Raptor,

All are taken from the Experts log file / journal log file.

 
There have been a couple of threads in recent months about doubling up of orders, could this be the same issue? I do not remember whether they were resolved or not
 

Hi,

i did think that, but i do not think this is the case in this example. the reason being is that the rogue trade is appearing BEFORE we get the logs in the expert log. If this was a double up trade, we would expect to see the expert log as normal, but then a second trade triggered after the first one had been sent through.

 
GreatSamps:

Hi,

i did think that, but i do not think this is the case in this example. the reason being is that the rogue trade is appearing BEFORE we get the logs in the expert log. If this was a double up trade, we would expect to see the expert log as normal, but then a second trade triggered after the first one had been sent through.


No it isn't, you actually say in your first post that it is the middle trade that is not in the Experts log.
 

Hi,

there are two trades in the experts log, and three in the journal. The first trade in the experts links up perfectly with the first trade in the journal, it is the next trade that is duplicated. I can tell that the middle trade is a copy of the last trade by looking at the unique ID we assign to the trades in their comment field.

was just about to post this, but thought why not double check, and your right, its the first trade that is duplicated.

this is good news because at least it explains why there is a lack of logging, but the double trade is still clearly a big issue.

don't suppose you have any links to those other threads?

 

ok, so found a couple of the other threads.

i see the some others had issues with multiple charts / terminals running. i checked all of that first of course, but the fact that 3 trades have appeared in this journal log means that this specific terminal sent them. (i tested this with 2 terminals different directories and they do not pick up trades placed by other terminals).

allowing for the print statements i have in the code, the only logical explanation is that the terminal is sending two orders.

this has happened 3 times over past week on 2 different accounts .....

New comment
Reason: