Советы профессионального программиста (Часть III): Логирование. Подключение к системе сбора и анализа логов Seq

Содержание

• Введение
• Seq — система сбора и анализа логов
• Класс Logger
• Тестирование класса Logger
• Импорт логов MetaTrader 5 в Seq
• Заключение

Введение

Логирование — это вывод сообщений для анализа работы приложений. Функции MQL5 Print и PrintFormat сохраняют свой вывод в журнал экспертов. Журнал экспертов — это текстовый файл в формате Unicode. Каждый день, чтобы не перегружать логи, создается новый файл MQL5/Logs/yyyymmdd.log.

Все скрипты и эксперты на всех открытых графиках "пишут лог" в один файл. При этом часть лога остается в дисковом кеше. Иначе говоря, если открыть файл лога из проводника, то вы не увидите в нем последнюю информацию, поскольку она находится в кеше. Чтобы заставить терминал сбросить (сохранить) кеш в файл, нужно либо завершить работу и закрыть терминал, либо через контекстное меню вкладки Эксперт выбрать пункт "Открыть". Откроется каталог с файлами логов.

Анализировать такие логи, особенно в терминале, не очень легко, но необходимо. В первой части советов я показал один из способов облегчения поиска, выборки и просмотра информации в логах терминала. В данной статье я покажу как:

• унифицировать вывод логов (класс Logger)
• подключить логи к системе сбора и анализа логов Seq
• просматривать сообщения (события) в режиме онлайн (в Seq)
• импортировать обычные логи МТ5 в Seq (пакет на Python)

Seq — система сбора и анализа логов

Seq — это сервер поиска и анализа логов приложений в режиме реального времени. Его тщательно продуманный пользовательский интерфейс, хранилище событий в формате JSON и язык SQL запросов делают его эффективной платформой для обнаружения и диагностики проблем в сложных приложениях и микросервисах.

Для передачи сообщений в Seq, необходимо:

1. Установить Seq на компьютер.
   После установки, интерфейс пользователя (UI) Seq будет доступен по адресу
   http://localhost:5341/#/events
2. Добавить в файл c:/windows/system32/drivers/etc/hosts строку
   127.0.0.1 seqlocal.net
   чтобы иметь возможность добавления URL в настройки Терминала МetaТrader 5
3. Запретить в Seq использование timezone, чтобы показывать время сообщений "как есть"   
   - перейти в UI Seq
   - перейти в admin/Preferences/Preferences   
   - включить пункт Show timestamps in Coordinated Universal Time (UTC)
4. Добавить в MT5/Tools/Options/Expert Advisors 
   http://seqlocal.net
   чтобы разрешить функции WebRequest использовать данный URL

Для наблюдения за сообщениями (событиями) в режиме онлайн нужно через UI Seq включить режим онлайн (кликнуть по кнопке Tail).

Класс Logger

Выскажу банальную мысль: чтобы получить унифицированную (структурированную) информацию, необходимо ее формировать и выводить одинаковым образом. Для этого предназначен класс Logger, он полностью автономный. Т.е. без дополнительных зависимостей в виде подключений #include. Как говорится, пользуйтесь прямо из коробки.

// уровни сообщений
#define LEV_DEBUG "DBG"   // отладка (для служебного пользования)
#define LEV_INFO "INF"    // информация (для отслеживания функционала)
#define LEV_WARNING "WRN" // предупреждение (обрати внимание)
#define LEV_ERROR "ERR"   // не критическая ошибка (смотри лог, работать можно)
#define LEV_FATAL "FTL"   // фатальная ошибка (работать нельзя)

Уровень сообщения дает приблизительное представление о важности (серьезности) и срочности сообщения. Чтобы в журнале эксперта уровни хорошо читались (выделялись и были выровнены), я обозначил их в виде трехбуквенных префиксов: DBG, INF, WRN, ERR, FTL. 

• DEBUG предназначен для программиста и во многих системах логгирования не выводится на консоль, но сохраняется в файл. DEBUG сообщения выводятся чаще других и как правило содержат наименования функций с параметрами и/или результатами их вызова.
• INFO предназначен для пользователя. Выводятся реже DEBUG-сообщений и содержит информацию о функционировании приложения. Например, действия пользователя (клик по пункту меню), результаты транзакций и прочее, т.е. все что может понять обычный пользователь.
• WARNING говорит о том, что на данную информацию надо обратить внимание. Например: открытие или закрытие сделки, срабатывание отложенного ордера и т.д. 
• ERROR говорит об ошибке, но не критической, после возникновения которой функционирование приложения продолжается. Например, недопустимый уровень цены или стопа в ордере, из-за которого ордер был отклонен (не исполнен).
• FATAL говорит о критической ошибке, после которой дальнейшая работа приложения (если она продолжится) в штатном режиме не гарантирована. Надо срочно остановить приложение и исправить ошибку.

Для читабельности и сокращения кода вывод сообщений проводится через следующие макроподстановки (макросы)

// макросы вывода сообщений
#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)

Таким образом, в каждом сообщении выводится имя файла (модуля), имя функции и само сообщение. Для формирования сообщения рекомендуется использовать функцию PrintFormat. При этом каждое значение желательно разделять подстрокой " / ". Такой прием делает все сообщения унифицированными (структурированными).

Пример операторов

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

Вывод данных операторов в журнал эксперта

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

Особенностью вывода сообщений в терминале МТ5 является тот факт, что в колонке Time время указывается локальное (TimeLocal), тогда как информация относится к серверному времени (TimeCurrent). Поэтому там, где нужно сделать акцент на время, необходимо указывать время в самом сообщении. Как это сделано во втором сообщении: 13:00 - локальное время, 12:00 - серверное время (реальное время открытия бара).

Класс Logger имеет следующую структуру

class Logger {
private:
    string  m_module;  // имя модуля(файла)
    string  m_sender;  // имя функции
    string  m_level;   // уровень сообщения
    string  m_message; // текст сообщения
    string  m_urlSeq;  // url сервиса сообщений Seq
    string  m_appName; // имя приложения для Seq
    // приватные методы
    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; // экземпляр логгера

Все лаконично, читабельно и ничего лишнего. Обратите внимание на объявление экземпляра логгера gLog. Переменные, объявленные как extern с одним и тем же типом и идентификатором, могут существовать в разных исходных файлах одного проекта. Extern-переменные можно инициализировать, но только однократно. Т.е. после создания логгера в любом файле проекта переменная gLog будет указывать на один и тот же объект.

// -----------------------------------------------------------------------------
// Конструктор
// -----------------------------------------------------------------------------
Logger::Logger(string appName, string urlSeq = "") {
    m_appName = appName;
    m_urlSeq = urlSeq;
}

Конструктор логгера принимает два параметра:

• appName - имя приложения для Seq. Система Seq может принимать логи от различных приложений в режиме онлайн. appName служит для фильтрации сообщений.
• urlSeq - URL сервиса Seq. Может представлять собой локальный сайт с прослушиванием определенного порта (http://localhost:5341/#/events).

Параметр urlSeq не обязателен. Если он не указан, то вывод сообщений будет только в журнал эксперта. Если urlSeq определен, то сообщения дополнительно будут отправляться через WebRequest сервису Seq.

// -----------------------------------------------------------------------------
// Установить отправителя сообщений
// -----------------------------------------------------------------------------
void Logger::SetSender(string module, string sender) { 
    m_module = module; // имя модуля (файла)
    m_sender = sender; // имя функции
    StringReplace(m_module, ".mq5", "");
}

Функция SetSender принимает два обязательных параметра и устанавливает отправителя сообщения. Из имени модуля удаляется расширение файла ".mq5". Если оператор логирования (LOG_LEVEL) используется в методе класса, то к имени функции добавится имя класса, например TestClass::TestFunc.

// -----------------------------------------------------------------------------
// Преобразовать время в формат ISO8601 для Seq
// -----------------------------------------------------------------------------
string Logger::TimeToStr(datetime value) {
    MqlDateTime mdt;
    TimeToStruct(value, mdt);
    ulong msec = GetTickCount64() % 1000; // для сравнения
    return StringFormat("%4i-%02i-%02iT%02i:%02i:%02i.%03iZ", 
        mdt.year, mdt.mon, mdt.day, mdt.hour, mdt.min, mdt.sec, msec);
}

Тип времени для Seq должен быть в формате ISO8601 (YYYY-MM-DDThh:mm:ss[.SSS]). Тип datetime в MQL5 рассчитывается с точностью до секунды. Время в Seq представляется с точностью до милисекунд. Поэтому к заданному времени искусственно (намеренно) добавляются количество миллисекунд, прошедших с момента старта системы (GetTickCount64). Такой прием позволит сравнить время сообщений относительно друг друга.

// -----------------------------------------------------------------------------
// Преобразовать период в строку
// -----------------------------------------------------------------------------
string Logger::PeriodToStr(ENUM_TIMEFRAMES value) {
    return StringSubstr(EnumToString(value), 7);
}

Период в Seq передается в символьном виде. Символьное представление любого периода имеет префикс "PERIOD_". Поэтому при преобразовании периода в строку префикс просто обрезается. Например PERIOD_H1 преобразуется в "H1".

Для отправки сообщения (регистрации события) в систему Seq используется функция SendToSeq

// -----------------------------------------------------------------------------
// Отправить сообщение в Seq через http
// -----------------------------------------------------------------------------
void Logger::SendToSeq() {

    // заменяем запрещенные символы
    StringReplace(m_message, "\n", " ");
    StringReplace(m_message, "\t", " ");
    
    // готовим строку в формате clef (Compact Logging Event 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())) + // время сообщения
        ",\"AppName\":" + Quote(m_appName) +          // имя приложения (Cayman)
        ",\"Symbol\":" + Quote(_Symbol) +             // символ (EURUSD)
        ",\"Period\":" + Quote(speriod) +             // период (H4)
        ",\"Module\":" + Quote(m_module) +            // имя модуля (__FILE__)
        ",\"Sender\":" + Quote(m_sender) +            // имя отправителя (__FUNCTION__)
        ",\"Level\":" + Quote(m_level) +              // уровень кратко (INF)
        ",\"@l\":" + Quote(Level()) +                 // уровень подробно (Information)
        ",\"Message\":" + Quote(m_message) +          // сообщение без доп.инф-ции
        ",\"@m\":" + Quote(extended_message) +        // сообщение с доп.инф-цией
    "}";

    // готовим данные для POST запроса
    char data[]; // массив данных тела HTTP-сообщения
    char result[]; // массив с данными ответа веб-сервиса
    string answer; // заголовки ответа веб-сервиса
    string headers = "Content-Type: application/vnd.serilog.clef\r\n";
    ArrayResize(data, StringToCharArray(clef, data, 0, WHOLE_ARRAY, CP_UTF8) - 1);

    // передаем сообщение в Seq через 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));
    }
}

Вначале символы перевода строки и табуляции заменяются на пробелы. Далее формируется JSON запись с параметрами сообщения в виде пар "ключ": "значение". Параметры с префиксом @ являются обязательными (служебными), остальные — пользовательскими. Имена и их количество определяет программист. Параметры и их значения могут быть использованы в SQL запросах.

Обратите внимание на время сообщения  @t = TimeCurrent(). Фиксируется серверное время, а не локальное (TimeLocal()), как в терминале. Далее формируется тело запроса, и затем через WebRequest оно передается в сервис Seq.

// -----------------------------------------------------------------------------
// Записать сообщение в лог
// -----------------------------------------------------------------------------
void Logger::Log(string level, string message) {
    
    m_level = level;
    m_message = message;
    
    // выводим сообщение в журнал эксперта (Toolbox/Experts)
    PrintFormat("%s: %s %s", m_level, m_sender, m_message);
    
    // если определен URL, то посылаем сообщение в Seq через http
    if (m_urlSeq != "") SendToSeq();
}

Функция принимает два обязательных параметра: уровень (срочность) сообщения и строку самого сообщения. Сообщение выводится в лог (журнал эксперта). При этом после уровня ставится символ двоеточия. Сделано это специально для Notepad++, чтобы подсвечивать строки (WRN: - черным на желтом, ERR: - желтым на красном).

Тестирование класса Logger

Для тестирования класса используется скрипт TestLogger.mq5. Макросы логирования использованы в различных функциях. 

#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 memery
    delete testObj;
    delete gLog;
}

Просмотр сообщений в журнале эксперта.  С сообщениях четко видны уровни и отправители (владельцы) сообщений.

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

Просмотр сообщений в редакторе Notepad++

Просмотр сообщений в Seq

Импорт логов MetaTrader 5 в Seq

Для импорта логов в Seq мной был создан пакет seq2log на Python. Не буду его описывать в данной статье. В пакете содержится файл README.md. Весь код достаточно подробно откомментирован. Пакет seq2log импортирует произвольные логи из журнала эксперта MQL5/Logs/yyyymmdd.log. Сообщениям без уровня важности присваивается уровень INF:

Где можно использовать seq2log? Например, вы разработчик (фрилансер) и просите у своего клиента прислать лог эксперта. Анализировать в текстовом редакторе можно, но в сервисе Seq это делать более комфортно за счет использования SQL запросов. Наиболее часто используемые или хитро составленные запросы можно хранить в Seq и исполнять одним кликом по имени запроса.

    Запуск: py log2seq appName pathLog
    где log2seq - имя пакета (каталога)
        appName - имя приложения для идентификации событий в Seq
        pathLog - путь лога МТ5
    Пример: py log2seq Cayman d:/Project/MQL5/Logs/20211028.log

Заключение

В статье описан класс Logger и способы его использования для:

• логирования структурированных сообщений с уровнями важности
• регистрации сообщений (событий) в системе сбора и анализа логов Seq

Исходники класса Logger и его теста прилагаются. Дополнительно прилагаются исходники пакета log2seq, написанного на Python, для импорта существующих логов МТ5 в сервис Seq.

Сервис Seq позволяет анализировать логи на профессиональном уровне с большими возможностями выборки и визуализации данных. Кроме того, исходники класса Logger позволяют добавить в сообщения логов данные, специально предназначенные для визуализации в виде графиков в Seq. Возможно, это сподвигнет вас на пересмотр состава отладочной информации в логах ваших приложений. Пробуйте, применяйте на практике. Удачи!