Conselhos de um programador profissional (Parte III): Registro de Logs. Conectando-se ao sistema Seq de coleta e análise de logs

Índice

• Introdução
• Seq: Sistema para coleta e análise de logs
• Classe Logger
• Testando a classe Logger
• Importando os logs da MetaTrader 5 para o Seq
• Conclusão

Introdução

Logging ou o registro de logs é a exibição de mensagens para analisar o funcionamento das aplicações. As funções MQL5 Print e PrintFormat salvam as mensagens de saída na guia Experts da caixa de ferramentas. A guia Expert é um arquivo de texto no formato Unicode. Um novo arquivo do tipo MQL5/Logs/aaaammdd.log é criado todos os dias para evitar a sobrecarga dos logs.

Todos os scripts e Expert Advisors em todos os gráficos abertos "gravam o log" num arquivo. Algumas partes do log permanecem na cache de disco. Em outras palavras, se você abrir o arquivo de log no explorer, você não verá as informações mais recentes nele, pois ela está na cache. Para forçar a plataforma a salvar o que está na cache num arquivo, você deve fechá-la ou usar o menu de contexto da guia Experts e selecionar o item Abrir. Isso abrirá um diretório com os arquivos de log.

Não é fácil analisar esses logs, principalmente na plataforma. Mas essa análise é muito importante. Na primeira parte dos conselhos, eu mostrei uma das formas de simplificar a busca, seleção e visualização de informações nos logs da plataforma. Neste artigo, eu mostrarei como:

• unificar a saída de log (classe Logger)
• conectar os logs ao sistema Seq de coleta e análise de logs
• ver mensagens (eventos) online no Seq
• importar logs regulares da MetaTrader 5 para o Seq (pacote Python)

Seq: Sistema para coleta e análise de logs

O Seq é um servidor para buscar e analisar os logs de aplicações em tempo real. A sua interface de usuário bem projetada, armazenamento de eventos no formato JSON e linguagem de consulta SQL o tornam uma plataforma eficaz para identificar e diagnosticar problemas em aplicações e microsserviços complexos.

Para enviar mensagens para o Seq, você precisa:

1. Instalar o Seq em seu computador.
   Após a instalação, a interface do usuário (UI) do Seq estará disponível em:
   http://localhost:5341/#/events
2. Adicionar a seguinte linha para o arquivo c:/windows/system32/drivers/etc/hosts:
   127.0.0.1 seqlocal.net
   para poder adicionar a URL às configurações da Plataforma MetaTrader 5
3. Desabilitar o uso do fuso horário no Seq para mostrar o horário exato da mensagem
   - vá para a UI do Seq
   - vá para admin/Preferences/Preferences
   - habilite "Show timestamps in Coordinated Universal Time (UTC)"
4. Adicionar o seguinte endereço em MT5/Tools/Options/Expert Advisors
   http://seqlocal.net
   para permitir que a função WebRequest use esta URL

Para monitorar as mensagens (eventos) online, você precisa habilitar o modo online através da UI do Seq clicando no botão Tail.

Classe Logger

A ideia é tão simples assim: Para obter as informações unificadas e estruturadas, ele deve ser formado e exibido da mesma forma. Para isso, nós usaremos a classe Logger que é completamente autônoma. Ou seja, não possui dependências adicionais como arquivos #include. Dessa forma, a classe está pronta para ser usada.

// 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)

O nível da mensagem dá uma ideia aproximada da gravidade e urgência da mensagem. Para ter os níveis bem legíveis na guia Experts, para tê-los destacados e alinhados, eu uso um prefixo de 3 letras para eles: DBG, INF, WRN, ERR, FTL. 

• DEBUG é destinado ao programador e em muitos sistemas de registro não é enviado para o console, mas é salvo num arquivo. As mensagens DEBUG são exibidas com mais frequência do que outras e geralmente contêm os nomes das funções com parâmetros e/ou seus resultados das chamadas.
• INFO é destinado ao usuário. Essas mensagens aparecem com menos frequência do que a mensagem DEBUG. Eles contêm informações sobre o funcionamento da aplicação. Por exemplo, podem ser ações do usuário, como clicar num item de menu, resultados de negócios etc., ou seja, tudo o que um usuário pode entender.
• WARNING indica que esta informação deve ser vista com atenção. Por exemplo: negócio aberto ou fechado, ordem pendente acionada, etc. 
• ERROR significa que houve um erro não crítico, após o qual a aplicação continua a funcionar. Por exemplo, um preço ou um nível de stop inválido de uma orderm, que fez ela ser rejeitada ou não ser executada.
• FATAL indica um erro crítico no qual a operação adicional da aplicação em modo normal não é garantida. Você precisa urgentemente interromper a aplicação e corrigir o erro.

Para legibilidade e redução de código, as mensagens são emitidas por meio das seguintes substituições de macro

// 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)

Assim, cada mensagem exibe o nome do arquivo ou o módulo, o nome da função e a própria mensagem. Para gerar uma mensagem, eu recomendo usar a função PrintFormat. É desejável separar cada valor com uma substring " / ". Essa técnica torna todas as mensagens unificadas e estruturadas.

Exemplo de operadores

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

Saída de dados do operador para o log da guia Experts

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

A característica específica das mensagens impressas na MetaTrader 5 é que a coluna Time especifica a hora local (TimeLocal), enquanto a informação realmente pertence à hora do servidor TimeCurrent. Portanto, onde for necessário enfatizar o horário, o horário deve ser especificado na própria mensagem. Isso é mostrado na segunda mensagem, onde 13:00 é a hora local e 12:00 é a hora do servidor (hora de abertura da barra real).

A classe Logger tem a seguinte estrutura

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

Tudo é conciso, legível e não contém detalhes desnecessários. Preste atenção na declaração da instância do logger gLog. As variáveis declaradas como 'extern' com o mesmo tipo e identificador podem existir em diferentes arquivos de origem do mesmo projeto. As variáveis externas podem ser inicializadas, mas apenas uma vez. Assim, após criar um logger em qualquer arquivo de projeto, a variável gLog apontará para o mesmo objeto.

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

O construtor do logger recebe dois parâmetros:

• appName - nome da aplicação para o Seq. O sistema Seq pode receber logs de diferentes aplicações no modo online. appName é usado para filtrar as mensagens.
• urlSeq - URL do serviço Seq. Pode ser um site local escutando numa porta específica (http://localhost:5341/#/events).

O parâmetro urlSeq é opcional. Se não for especificado, as mensagens serão enviadas apenas para a guia Experts. Se a urlSeq estiver definida, os eventos serão enviados adicionalmente via WebRequest para o serviço Seq.

// -----------------------------------------------------------------------------
// 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", "");
}

A função SetSender obtém dois parâmetros necessários e define o remetente da mensagem. A extensão do arquivo ".mq5" é removida do nome do módulo. Se o operador de log LOG_LEVEL for usado num método da classe, o nome da classe será adicionado ao nome da função, por exemplo 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);
}

O tipo de hora para o Seq deve estar no formato ISO8601 (AAAA-MM-DDThh:mm:ss[.SSS]). O tipo de data e hora em MQL5 é calculado em até um segundo. O horário em Seq é representado até um milissegundo. Portanto, o número de milissegundos decorridos desde o início do sistema (GetTickCount64) é adicionado à hora especificada. Este método permitirá que você compare o tempo das mensagens em relação umas às outras.

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

O período é passado para Seq de forma simbólica. A representação simbólica de qualquer período é prefixada com "PERIOD_". Portanto, ao converter um ponto numa string, o prefixo é simplesmente truncado. Por exemplo, PERIOD_H1 é convertido em "H1".

A função SendToSeq é usada para enviar uma mensagem (para registrar um evento) para 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));
    }
}

Primeiro, as novas linhas e tabulações são substituídas por espaços. Em seguida, um registro JSON com parâmetros de mensagem como pares "chave": "valor" é formado então. Os parâmetros com o prefixo @ são obrigatórios (serviço), os demais são definidos pelo usuário. Os nomes e seus números são determinados pelo programador. Os parâmetros e seus valores podem ser usados em consultas SQL.

Preste atenção ao tempo da mensagem @t = TimeCurrent(). Ele corrige a hora do servidor, mas não a local (TimeLocal()), em contraste com a da plataforma. Em seguida, o corpo da solicitação é formado e é enviado para o serviço Seq 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();
}

A função tem dois parâmetros obrigatórios: o nível de gravidade da mensagem e a string da mensagem. A mensagem é impressa na guia Expert da caixa de ferramentas. O nível é seguido por um caractere de dois pontos. Isso foi feito especificamente para o Notepad++ para destacar as linhas (WRN: - preto em amarelo, ERR: - amarelo em vermelho).

Testando a classe Logger

O script TestLogger.mq5 é usado para testar a classe. As macros de registro são usadas em várias funções. 

#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;
}

Visualizando as mensagens na guia Experts. As mensagens mostram claramente os níveis e os remetentes das mensagens (proprietários).

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

Visualizando as mensagens no editor Notepad++

Visualizando as mensagens no Seq

Importando os logs da MetaTrader 5 para o Seq

Para importar os logs para o Seq, eu criei o pacote seq2log em Python. Eu não vou descrevê-lo neste artigo. O pacote contém o arquivo README.md. O código contém comentários detalhados. O pacote seq2log importa os logs arbitrários da guia Experts MQL5/Logs/aaaammdd.log. As mensagens sem nível de importância recebem o nível INF:

Onde o seq2log pode ser usado? Por exemplo, se você é um desenvolvedor Freelance, você pode pedir ao seu cliente que envie os logs do Expert. É possível analisar os logs num editor de texto, mas é mais conveniente no Seq através do uso de consultas SQL. As consultas mais usadas ou complexas podem ser armazenadas no Seq e executadas com um único clique no nome da consulta.

    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

Conclusão

Este artigo descreve a classe Logger e como usá-la para:

• registrar as mensagens estruturadas com níveis de gravidade
• registrar as mensagens (eventos) no sistema Seq de coleta e análise de log

Os códigos-fonte da classe Logger e seus testes estão anexados. Além disso, o anexo contém o código-fonte Python do pacote log2seq que é usado para importar os logs existentes da MetaTrader 5 para o Seq.

O serviço Seq permite a análise de logs em nível profissional. Ele oferece excelentes recursos de amostragem e visualização de dados. Além disso, o código-fonte da classe Logger permite adicionar às mensagens de log os dados especialmente projetados para visualização - para desenhar diagramas no Seq. Isso pode incentivá-lo a revisar as informações de depuração nos logs da sua aplicação. Experimente aplicá-lo na prática. Boa sorte!