Benefícios do Log Estruturado vs Log Básico

Existem dois avanços fundamentais com a abordagem estruturada que não podem ser emulados usando logs de texto sem (por vezes níveis extremos) esforço adicional.

Tipos de evento

Quando você escreve dois eventos com log4net como:

log.Debug("Disk quota {0} exceeded by user {1}", 100, "DTI-Matt");
log.Debug("Disk quota {0} exceeded by user {1}", 150, "nblumhardt");

Estes produzirão texto semelhante:

Disk quota 100 exceeded by user DTI-Matt
Disk quota 150 exceeded by user nblumhardt

Mas, no que diz respeito ao processamento de máquinas, elas são apenas duas linhas de texto diferente.

Você pode querer encontrar todos os eventos de "cota de disco excedido", mas o caso simplista de procurar eventos like 'Disk quota%' cairá tão logo ocorra outro evento parecido com:

Disk quota 100 set for user DTI-Matt

O log de texto elimina as informações que temos inicialmente sobre a origem do evento, e isso deve ser reconstruído ao ler os logs normalmente com expressões de correspondência mais elaboradas.

Por outro lado, quando você escreve os dois eventos Serilog seguintes:

log.Debug("Disk quota {Quota} exceeded by user {Username}", 100, "DTI-Matt");
log.Debug("Disk quota {Quota} exceeded by user {Username}", 150, "nblumhardt");

Estes produzem uma saída de texto semelhante à versão do log4net, mas por trás das cenas, o modelo de mensagem "Disk quota {Quota} exceeded by user {Username}" é carregado pelos dois eventos.

Com um coletor apropriado, você pode mais tarde gravar as consultas where MessageTemplate = 'Disk quota {Quota} exceeded by user {Username}' e obter exatamente os eventos em que a cota de disco foi excedida.

Nem sempre é conveniente armazenar o modelo de mensagem inteiro em cada evento de log, portanto, alguns coletores fazem o modelo de mensagem em um valor EventType numérico (por exemplo, 0x1234abcd ) ou você pode adicionar um enfileiramento ao pipeline de registro para faça você mesmo .

É mais sutil do que a próxima diferença abaixo, mas é maciçamente poderosa quando se lida com grandes volumes de log.

Dados estruturados

Novamente considerando os dois eventos sobre o uso de espaço em disco, pode ser fácil usar logs de texto para consultar um usuário em particular com like 'Disk quota' and like 'DTI-Matt' .

Mas, os diagnósticos de produção nem sempre são tão diretos. Imagine que é necessário encontrar eventos em que a cota de disco excedida estava abaixo de 125 MB?

Com o Serilog, isso é possível na maioria dos coletores usando uma variante de:

Quota < 125

Construir esse tipo de consulta a partir de uma expressão regular é possível, mas fica cansativo rapidamente e geralmente acaba sendo uma medida de último recurso.

Agora, adicione a isso um tipo de evento:

Quota < 125 and EventType = 0x1234abcd

Você começa a ver aqui como esses recursos se combinam de maneira direta para tornar a depuração de produção com logs uma atividade de desenvolvimento de primeira classe.

Quando você está coletando logs para processamento, seja para análise em algum banco de dados e / ou pesquisando os logs processados mais tarde, o uso do registro estruturado facilita ou torna mais eficiente o processamento. O analisador pode tirar proveito da estrutura conhecida (por exemplo, JSON, XML, ASN.1, qualquer que seja) e usar máquinas de estado para análise, em oposição a expressões regulares (que podem ser computacionalmente caras (relativamente) para compilar e executar). A análise de texto de forma livre, como a sugerida por seu colega de trabalho, tende a depender de expressões regulares, e para confiar em que o texto não seja alterado . Isso pode tornar a análise de texto de formato livre um pouco frágil (a análise i.e. é strongmente acoplada ao texto exato no código).

Considere também o caso de pesquisa / pesquisa, por exemplo. :

SELECT text FROM logs WHERE text LIKE "Disk quota";

LIKE exigem comparações com todos os valores de text row; Novamente, isso é relativamente computacionalmente caro, particularmente por isso quando curingas são usados:

SELECT text FROM logs WHERE text LIKE "Disk %";

Com o registro estruturado, sua mensagem de log relacionada a erro de disco pode ter esta aparência em JSON:

{ "level": "DEBUG", "user": "username", "error_type": "disk", "text": "Disk quota ... exceeded by user ..." }

Os campos desse tipo de estrutura podem ser mapeados facilmente para , por exemplo, nomes de coluna da tabela SQL, o que significa que a pesquisa pode ser mais específica / granular:

SELECT user, text FROM logs WHERE error_type = "disk";

Você pode colocar índices nas colunas cujos valores você espera pesquisar / pesquisar com freqüência, contanto que não use cláusulas LIKE para esses valores de coluna . Quanto mais você conseguir dividir sua mensagem de registro em categorias específicas, mais direcionada poderá fazer sua pesquisa. Por exemplo, além do campo error_type / coluna no exemplo acima, você pode até mesmo ser "error_category": "disk", "error_type": "quota" ou algo assim.

Quanto mais estrutura você tiver em suas mensagens de log, mais seus sistemas de análise / pesquisa (como fluentd , elasticsearch , kibana ) poderão aproveitar essa estrutura e executar suas tarefas com maior velocidade e menos CPU / memória.

Espero que isso ajude!

Você não encontrará muitos benefícios com o registro estruturado quando seu aplicativo criar algumas centenas de mensagens de registro por dia. Você definitivamente o fará quando tiver algumas centenas de mensagens de log por segundo provenientes de muitos aplicativos implantados diferentes.

Relacionada, a configuração em que as mensagens de log terminam em a Pilha ELK também é apropriada para escala, onde logging para SQL torna-se um gargalo.

Eu vi a configuração de "registro e pesquisa básicos" com SQL select .. like e regexps levados a seus limites onde eles se desfazem - há falsos positivos, omissões, códigos de filtro horríveis com erros conhecidos que são difíceis de manter e não -que quer tocar, novas mensagens de log que não seguem as suposições do filtro, relutância em tocar as instruções de log no código para não quebrar relatórios, etc.

Então, vários pacotes de software estão surgindo para lidar com esse problema de uma maneira melhor. Existe o Serilog, eu ouvi dizer que a equipe do NLog está olhando para ele , e nós escrevemos StructuredLogging.Json para o Nlog , também vejo que o novo Abstrações de criação de log do núcleo ASP.Net "tornam possível que os provedores de registro implementem ... registro estruturado".

Um exemplo com o StructuredLogging. Você loga em um logger NLog assim:

logger.ExtendedError("Order send failed", new { OrderId = 1234, RestaurantId = 4567 } );

Esses dados estruturados vão para o kibana. O valor 1234 é armazenado no campo OrderId da entrada de log. Você pode então pesquisar usando a sintaxe de consulta do kibana por exemplo todas as entradas de log em que @LogType:nlog AND Level:Error AND OrderId:1234 .

Message e OrderId agora são apenas campos que podem ser pesquisados para correspondências exatas ou inexatas conforme necessário ou agregadas para contagens. Isso é poderoso e flexível.

A partir das práticas recomendadas do StructuredLogging :

The message logged should be the same every time. It should be a constant string, not a string formatted to contain data values such as ids or quantities. Then it is easy to search for.

The message logged should be distinct i.e. not the same as the message produced by an unrelated log statement. Then searching for it does not match unrelated things as well.