When a client tells me their EA "did something weird last night," the first thing I ask for is the log. Too often there is nothing useful in it. The Experts tab shows that the EA loaded, maybe a few lines from the terminal about orders, and that is all. Without a record of what the EA saw and decided, debugging turns into guessing.
Here is how I add logging to the EAs I build, so that a strange trade can be explained in a few minutes.
What to log
I log decisions, not ticks. Printing every tick floods the journal and hides the lines that matter. The events worth a line are:
- Startup: EA version, symbol, timeframe, account type, key input values, and the broker's digits, point and volume step for the symbol.
- Signals: when an entry or exit condition becomes true, with the values that triggered it, such as the indicator readings and the bar time.
- Skipped trades: when a signal fires but a filter blocks it, with the reason. Spread too wide, outside session hours, daily limit reached, position already open.
- Every trade request and its result, including the return code.
- State changes: a breakeven move, a trailing stop update, a daily lock switching on or off.
The skipped trade lines are the ones people forget, and they answer the most common question I get: "Why didn't it take that trade?"
Print vs FileWrite
Print writes to the Experts tab and to the terminal's daily log in the MQL5/Logs folder. It is quick to add and fine for development. The downside is that it mixes your lines with everything else the terminal writes, and the format is not easy to load into a spreadsheet.
For live accounts I also write to my own file with FileOpen and FileWrite. That gives me one file per EA and per symbol, a consistent column layout, and something I can open in a spreadsheet or search with a script. I keep Print for the important lines too, so they still show up in the terminal while I am watching.
int g_log = INVALID_HANDLE;
bool LogOpen()
{
MqlDateTime d;
TimeToStruct(TimeCurrent(), d);
string name = StringFormat("MyEA_%s_%04d%02d%02d.csv",
_Symbol, d.year, d.mon, d.day);
g_log = FileOpen(name, FILE_WRITE | FILE_READ | FILE_CSV |
FILE_SHARE_READ | FILE_ANSI, ';');
if(g_log == INVALID_HANDLE) return false;
FileSeek(g_log, 0, SEEK_END); // append, do not overwrite
return true;
}
void Log(string event, string detail)
{
string t = TimeToString(TimeCurrent(), TIME_DATE | TIME_SECONDS);
if(g_log != INVALID_HANDLE)
{
FileWrite(g_log, t, _Symbol, event, detail);
FileFlush(g_log);
}
Print(event, " | ", detail);
}
FileFlush after each write matters. If the terminal crashes or the VPS reboots, unflushed lines are lost, and those are usually the lines you needed.
Log rotation
A busy EA can write a lot over a few months. I put the date in the file name, as above, and open a new file when the server date changes. On startup the EA can delete files older than a set number of days from its own folder. Files live in the terminal's MQL5/Files sandbox, so the EA can only touch its own files, which keeps this safe.
Logging order results and retcodes
The single most useful line in any EA log is the trade result. A request that returns true from OrderSend is not the same as a filled order. I log the requested price and volume next to what came back.
#include <Trade/Trade.mqh>
CTrade trade;
void LogResult(string action)
{
Log(action, StringFormat(
"retcode=%u (%s) req_price=%.5f fill_price=%.5f vol=%.2f deal=%I64u",
trade.ResultRetcode(), trade.ResultRetcodeDescription(),
trade.RequestPrice(), trade.ResultPrice(),
trade.ResultVolume(), trade.ResultDeal()));
}
With that line in place, requotes, invalid stops, market closed errors and partial fills stop being mysteries. You can also measure slippage directly by comparing the requested and filled price.
Reading logs: live vs backtest
In the Strategy Tester, Print output goes to the tester journal, and files are written to the tester agent's own Files folder rather than the terminal's. That catches people out the first time they look for their log after a test.
My routine when live behaviour differs from a backtest is simple. I run the tester over the same days, with the same inputs, and log in the same format. Then I put the two files side by side and find the first line where they disagree. Usually it is a signal that fired on a different bar, a filter that blocked a trade live because of spread, or a retcode the tester never produced. Once you know the first point of divergence, the cause is rarely far away.
Good logging takes an hour to add and saves days later. I treat it as part of the EA, not an extra.
I build custom MT5 Expert Advisors at Custom Trading Bots.
Top comments (4)
The server-date rotation needs one more step around this sample: close the old handle and reopen the dated file before writing the first event of the new day. Otherwise an EA kept running overnight can keep writing into yesterday's file. Do you check that date before each logged decision?
Good catch, Arnold. Yes, the check should happen before every write, not only on a timer. My usual pattern is a small helper that compares the date from TimeTradeServer with the date of the open file. If the day changed, it closes the old handle, opens the new dated file and only then writes the event. That way an EA that runs through midnight never logs into yesterday's file.
That ordering also needs a failure path. If opening the new dated file fails, I would log that failure through Print and keep the file logger unavailable, rather than silently reuse yesterday's handle. A rollover test with a deliberately failed FileOpen would make that visible.
Agreed. If FileOpen for the new dated file fails I Print the error, set the file handle invalid, and keep logging through Print only until the next successful open. Silently keeping yesterday's handle hides the rollover bug. A unit style test that forces FileOpen to fail on the date change is a good addition to the checklist.