Tips from a professional programmer (Part III): Logging. Connecting to the Seq log collection and analysis system

Table of contents

• Introduction
• Seq: System for collecting and analyzing logs
• Logger class
• Testing the Logger class
• Importing MetaTrader 5 logs to Seq
• Conclusion

Introduction

Logging is the output of messages for analyzing the operation of applications. MQL5 Print and PrintFormat functions save the output messages to the Experts journal. The Expert journal is a text file in the Unicode format. A new MQL5/Logs/yyyymmdd.log file is created every day to avoid log overloads.

All scripts and Expert Advisors on all open charts "write the log" to one file. Some log parts remain in the disk cache. In other words, if you open the log file from the explorer, you will not see the latest information in it, since it is in the cache. To force the terminal to save the cache to a file, you should either close the terminal, or use the context menu of the Experts tab and select the Open item in it. This will open a directory with the log files.

It is not easy to analyze these logs, especially in the terminal. But such analysis is very important. In the first part of the tips, I showed one of the ways to simplify search, selection and viewing of information in the terminal logs. In this article, I'll show you how to:

• unify log output (Logger class)
• connect logs to the Seq log collection and analysis system
• view messages (events) online in Seq
• import regular MetaTrader 5 logs into Seq (Python package)

Seq: System for collecting and analyzing logs

Seq is a server for searching and analyzing application logs in real time. Its well-designed user interface, event storage in JSON format, and SQL query language make it an effective platform for identifying and diagnosing problems in complex applications and microservices.

To send messages to Seq, you need to:

1. Install Seq on our computer.
   After installation, Seq UI will be available at:
   http://localhost:5341/#/events
2. Add the following line to the file c:/windows/system32/drivers/etc/hosts:
   127.0.0.1 seqlocal.net
   in order to be able to add URL to the MetaTrader 5 Terminal settings
3. Disable use of timezone in Seq to show message time "as is"
   - go to UI Seq
   - go to admin/Preferences/Preferences
   - enable "Show timestamps in Coordinated Universal Time (UTC)"
4. Add the following address to MT5/Tools/Options/Expert Advisors 
   http://seqlocal.net
   to allow the WebRequest function to use this URL

To watch messages (events) online, you need to enable online mode through UI Seq by clicking on the Tail button.

Logger class

The idea is as simple as this: In order to obtain unified and structured information, in should be formed and displayed in the same way. For this purpose, we will use the Logger class which is  completely autonomous. I.e., it does not have any additional dependencies as #include files. So, the class can be used "out of the box".

// Message levels
#define LEV_DEBUG "DBG"   // debugging (for service use)
#define LEV_INFO "INF"    // information (to track the functions)
#define LEV_WARNING "WRN" // warning (attention)
#define LEV_ERROR "ERR"   // a non-critical error (check the log, work can be continued)
#define LEV_FATAL "FTL"   // fatal error (work cannot be continued)

The message level gives a rough idea of the severity and urgency of the message. To have the levels well-readable in the Experts journal, to have them highlighted and aligned, I use 3-letter prefixes for them: DBG, INF, WRN, ERR, FTL. 

• DEBUG is intended for the programmer and in many logging systems is not output to the console but is saved to a file. DEBUG messages are displayed more often than others and usually contain the names of functions with parameters and/or their call results.
• INFO is intended for the user. These messages appear less frequently than DEBUG message. They contain information about the operation of the application. For example, these can be user actions, such as clicking on a menu item, transaction results etc., i.e. everything that a user can understand.
• WARNING indicates that this information should be paid attention to. For example: deal opened or closed, pending order triggered, etc. 
• ERROR means there was a non-critical error, after which the application continues to function. For example, an invalid price or stop level in an order, due to which the order was rejected or was not executed.
• FATAL indicates a critical error after which further application operation in a normal mode is not guaranteed. You urgently need to stop the application and fix the error.

For readability and code reduction, the messages are output through the following macro substitutions

// Message output macros
#define LOG_SENDER gLog.SetSender(__FILE__, __FUNCTION__)
#define LOG_INFO(message) LOG_SENDER; gLog.Info(message)
#define LOG_DEBUG(message) LOG_SENDER; gLog.Debug(message)
#define LOG_WARNING(message) LOG_SENDER; gLog.Warning(message)
#define LOG_ERROR(message) LOG_SENDER; gLog.Error(message)
#define LOG_FATAL(message) LOG_SENDER; gLog.Fatal(message)

Thus, each message displays the name of the file or module, the name of the function, and the message itself. To form a message, I recommend using the PrintFormat function. It is desirable to separate each value with the substring " / ". This technique makes all messages unified and structured.

Example of operators

LOG_INFO(m_result);
LOG_INFO(StringFormat("%s / %s / %s", StringSubstr(EnumToString(m_type), 3), 
    TimeToString(m_time0Bar), m_result));

Operator data output to the Experts log

Time                     Source              Message
---------------------------------------------------------------------------------------------------------------------
2022.02.16 13:00:06.079  Cayman (GBPUSD,H1)  INF: AnalyserRollback::Run Rollback, H1, 12:00, R1, D1, RO, order 275667165
2022.02.16 13:00:06.080  Cayman (GBPUSD,H1)  INF: Analyser::SaveParameters Rollback / 2022.02.16 12:00 / Rollback, H1, 12:00, R1, D1, RO, order 275667165

The specific feature of messages printed in MetaTrader 5 is that the Time column specifies TimeLocal, while information actually belongs to server time TimeCurrent. Therefore, where it is necessary to emphasize time, time should be specified in the message itself. This is shown in the second message, where 13:00 is local time and 12:00 is server time (real bar open time).

The Logger class has the following structure

class Logger {
private:
    string  m_module;  // module or file name
    string  m_sender;  // function name
    string  m_level;   // message level
    string  m_message; // message text
    string  m_urlSeq;  // url of the Seq message service
    string  m_appName; // application name for Seq
    // private methods
    void Log(string level, string message);
    string TimeToStr(datetime value);
    string PeriodToStr(ENUM_TIMEFRAMES value);
    string Quote(string value);
    string Level();
    void SendToSeq();
public:
    Logger(string appName, string urlSeq);
    void SetSender(string module, string sender);
    void Debug(string message) { Log(LEV_DEBUG, message); };
    void Info(string message) { Log(LEV_INFO, message); };
    void Warning(string message) { Log(LEV_WARNING, message); };
    void Error(string message) { Log(LEV_ERROR, message); };
    void Fatal(string message) { Log(LEV_FATAL, message); };
};

extern Logger *gLog; // logger instance

Everything is concise, readable and does not contain any unnecessary details. Pay attention to the declaration of the gLog logger instance. Variables declared as 'extern' with the same type and identifier may exist in different source files of the same project. Extern variables can be initialized but only once. So, after creating a logger in any project file, the gLog variable will point to the same object.

// -----------------------------------------------------------------------------
// Constructor
// -----------------------------------------------------------------------------
Logger::Logger(string appName, string urlSeq = "") {
    m_appName = appName;
    m_urlSeq = urlSeq;
}

The logger constructor receives two parameters:

• appName - application name for Seq. The Seq system can receive logs from different applications in the online mode. appName is used to filter messages.
• urlSeq - URL of the Seq service. It can be a local site listening on a specific port (http://localhost:5341/#/events).

The urlSeq parameter is optional. If it is not specified, then messages will be output only to the Experts log. If urlSeq is defined, the events will be additionally sent via WebRequest to the Seq service.

// -----------------------------------------------------------------------------
// Set the message sender          
// -----------------------------------------------------------------------------
void Logger::SetSender(string module, string sender) { 
    m_module = module; // module or file name
    m_sender = sender; // function name
    StringReplace(m_module, ".mq5", "");
}

The SetSender function gets two required parameters and sets the sender of the message. The ".mq5" file extension is removed from the module name. If the logging operator LOG_LEVEL is used in a class method, then the class name will be added to the function name, for example TestClass::TestFunc.

// -----------------------------------------------------------------------------
// Convert time to the ISO8601 format for Seq
// -----------------------------------------------------------------------------
string Logger::TimeToStr(datetime value) {
    MqlDateTime mdt;
    TimeToStruct(value, mdt);
    ulong msec = GetTickCount64() % 1000; // for comparison
    return StringFormat("%4i-%02i-%02iT%02i:%02i:%02i.%03iZ", 
        mdt.year, mdt.mon, mdt.day, mdt.hour, mdt.min, mdt.sec, msec);
}

Time type for Seq must be in the ISO8601 format (YYYY-MM-DDThh:mm:ss[.SSS]). The datetime type in MQL5 is calculated up to a second. Time in Seq is represented up to a millisecond. Therefore, the number of milliseconds that have elapsed since the system start (GetTickCount64) is forcedly added to the specified time. This method will allow you to compare the time of messages relative to each other.

// -----------------------------------------------------------------------------
// Convert period to string
// -----------------------------------------------------------------------------
string Logger::PeriodToStr(ENUM_TIMEFRAMES value) {
    return StringSubstr(EnumToString(value), 7);
}

Period is passed to Seq in symbolic form. The symbolic representation of any period is prefixed with "PERIOD_". Therefore, when converting a period to a string, the prefix is simply truncated. For example, PERIOD_H1 is converted to "H1".

The SendToSeq function is used to send a message (to register an event) to Seq

// -----------------------------------------------------------------------------
// Send message to Seq via http
// -----------------------------------------------------------------------------
void Logger::SendToSeq() {

    // replace illegal characters
    StringReplace(m_message, "\n", " ");
    StringReplace(m_message, "\t", " ");
    
    // prepare a string in the CLEF (Compact Logging Event Format) format
    string speriod = PeriodToStr(_Period);
    string extended_message = StringFormat("%s, %s / %s / %s / %s",
        _Symbol, speriod, m_module, m_sender, m_message);
    string clef = "{" +
        "\"@t\":" + Quote(TimeToStr(TimeCurrent())) + // event time
        ",\"AppName\":" + Quote(m_appName) +          // application name (Cayman)
        ",\"Symbol\":" + Quote(_Symbol) +             // symbol (EURUSD)
        ",\"Period\":" + Quote(speriod) +             // period (H4)
        ",\"Module\":" + Quote(m_module) +            // module name (__FILE__)
        ",\"Sender\":" + Quote(m_sender) +            // sender name (__FUNCTION__)
        ",\"Level\":" + Quote(m_level) +              // level abbreviation (INF)
        ",\"@l\":" + Quote(Level()) +                 // level details (Information)
        ",\"Message\":" + Quote(m_message) +          // message without additional info
        ",\"@m\":" + Quote(extended_message) +        // message with additional info
    "}";

    // prepare data for POST request
    char data[]; // HTTP message body data array
    char result[]; // Web service response data array
    string answer; // Web service response headers
    string headers = "Content-Type: application/vnd.serilog.clef\r\n";
    ArrayResize(data, StringToCharArray(clef, data, 0, WHOLE_ARRAY, CP_UTF8) - 1);

    // send message to Seq via http
    ResetLastError();
    int rcode = WebRequest("POST", m_urlSeq, headers, 3000, data, result, answer);
    if (rcode > 201) {
        PrintFormat("%s / rcode=%i / url=%s / answer=%s / %s", __FUNCTION__, 
            rcode, m_urlSeq, answer, CharArrayToString(result));
    }
}

First, newlines and tabs are replaced with spaces. Then a JSON record with message parameters as "key": "value" pairs is formed then. Parameters with the @ prefix are mandatory (service), the rest are user-defined. The names and their number are determined by the programmer. Parameters and their values can be used in SQL queries.

Pay attention to the message time @t = TimeCurrent(). It fixes server time, but not local (TimeLocal()), in contrast to the terminal. Next, the request body is formed and then sent to the Seq service via WebRequest.

// -----------------------------------------------------------------------------
// Write a message to log
// -----------------------------------------------------------------------------
void Logger::Log(string level, string message) {
    
    m_level = level;
    m_message = message;
    
    // output a message to the expert log (Toolbox/Experts)
    PrintFormat("%s: %s %s", m_level, m_sender, m_message);
    
    // if a URL is defined, then send a message to Seq via http
    if (m_urlSeq != "") SendToSeq();
}

The function has two required parameters: message severity level and the message string. The message is printed to the Expert journal. The level is followed by a colon character. This was done specifically for Notepad++ to highlight lines (WRN: - black on yellow, ERR: - yellow on red).

Testing the Logger class

The TestLogger.mq5 script is used to test the class. Logging macros are used in various functions. 

#include <Cayman/Logger.mqh>

class TestClass {
    int m_id;
public:
    TestClass(int id) { 
        m_id = id;
        LOG_DEBUG(StringFormat("create object with id = %i", id));
    };
};

void TestFunc() {
    LOG_INFO("info message from inner function");
}

void OnStart() {

    string urlSeq = "http://seqlocal.net:5341/api/events/raw?clef";
    gLog = new Logger("TestLogger", urlSeq);
    
    LOG_DEBUG("debug message");
    LOG_INFO("info message");
    LOG_WARNING("warning message");
    LOG_ERROR("error message");
    LOG_FATAL("fatal message");
    
    // call function
    TestFunc();
    
    // create object
    TestClass *testObj = new TestClass(101);

    // free memory
    delete testObj;
    delete gLog;
}

Viewing messages in the Experts log. Messages clearly show levels and message senders (owners).

2022.02.16 20:17:21.048 TestLogger (USDJPY,H1)  DBG: OnStart debug message
2022.02.16 20:17:21.291 TestLogger (USDJPY,H1)  INF: OnStart info message
2022.02.16 20:17:21.299 TestLogger (USDJPY,H1)  WRN: OnStart warning message
2022.02.16 20:17:21.303 TestLogger (USDJPY,H1)  ERR: OnStart error message
2022.02.16 20:17:21.323 TestLogger (USDJPY,H1)  FTL: OnStart fatal message
2022.02.16 20:17:21.328 TestLogger (USDJPY,H1)  INF: TestFunc info message from inner function
2022.02.16 20:17:21.332 TestLogger (USDJPY,H1)  DBG: TestClass::TestClass create object with id = 101

Viewing messages in Notepad++ editor

Viewing messages in Seq

Importing MetaTrader 5 logs to Seq

To import logs into Seq, I created the seq2log package in Python. I will not describe it in this article. The package contains the README.md file. The code contains detailed comments. The seq2log package imports arbitrary logs from the Experts journal MQL5/Logs/yyyymmdd.log. Messages with no importance level are assigned the INF level:

Where can seq2log be used? For example, if you are a Freelance developer, you can ask your client to send an expert log. It is possible to analyze logs in a text editor, but it is more convenient in Seq through the use of SQL queries. The most frequently used or complex queries can be stored in Seq and executed with a single click on the query name.

    Run: py log2seq appName pathLog
    where log2seq - package name
        appName - application name to identify events in Seq
        pathLog - MetaTrader 5 log path
    Example: py log2seq Cayman d:/Project/MQL5/Logs/20211028.log

Conclusion

This article describes the Logger class and how to use it to:

• log structured messages with severity levels
• register messages (events) in the Seq log collection and analysis system

The source codes of the Logger class and its test are attached. Additionally, the attachment contains source Python code of the log2seq package which is used for importing existing MetaTrader 5 logs into Seq.

The Seq service allows the analysis of logs on a professional level. It offers great data sampling and visualization capabilities. In addition, the Logger class source code allows adding to log messages the data that is specially designed for visualization - for drawing diagrams in Seq. This may encourage you to review the debug information in your application logs. Try applying it in practice. Good luck!