Avantages de la journalisation structurée par rapport à la journalisation de base

Nous construisons une nouvelle application et j'aimerais inclure la journalisation structurée. Ma configuration idéale serait quelque chose comme Serilogpour notre code C #, et Bunyanpour notre JS. Celles-ci allaient alimenter fluentdet pouvaient ensuite déboucher sur un certain nombre de choses, je pensais au début elasticsearch + kibana. Nous avons déjà une base de données MySQL, donc à court terme, je suis plus intéressé par l’installation de Serilog + Bunyan et par les développeurs qui l’utiliseront. Nous pouvons nous connecter à MySQL pendant que nous prenons un peu plus de temps pour introduire couramment le reste.

Cependant, l'un de nos codeurs les plus expérimentés préférerait faire quelque chose comme: log.debug("Disk quota {0} exceeded by user {1}", quota, user);utiliser log4netpuis exécuter simplement des instructions de sélection sur MySQL comme:SELECT text FROM logs WHERE text LIKE "Disk quota";

Cela étant dit, quelle approche est la meilleure et / ou quels éléments devons-nous prendre en compte lors du choix du type de système d'exploitation?

L' approche structurée présente deux avancées fondamentales qui ne peuvent pas être émulées à l'aide de journaux de texte sans effort supplémentaire (parfois extrême).

Types d'événements

Lorsque vous écrivez deux événements avec log4net comme:

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

Ceux-ci produiront un texte similaire:

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

Mais, en ce qui concerne le traitement par machine, ce ne sont que deux lignes de texte différent.

Vous souhaiterez peut-être rechercher tous les événements "quota de disque dépassé", mais le cas simpliste de recherche d'événements like 'Disk quota%'tombera dès qu'un autre événement se produisant ressemblant à ceci:

Disk quota 100 set for user DTI-Matt

La journalisation de texte supprime les informations dont nous disposions initialement sur la source de l'événement. Cette information doit être reconstituée lors de la lecture des journaux, généralement avec des expressions de correspondance de plus en plus élaborées.

En revanche, lorsque vous écrivez les deux événements Serilog suivants :

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

Celles-ci produisent une sortie texte similaire à la version log4net, mais en coulisse, le "Disk quota {Quota} exceeded by user {Username}" modèle de message est porté par les deux événements.

Avec un récepteur approprié, vous pouvez ultérieurement écrire des requêtes where MessageTemplate = 'Disk quota {Quota} exceeded by user {Username}'et obtenir exactement les événements pour lesquels le quota de disque a été dépassé.

Il n'est pas toujours pratique de stocker le modèle de message entier avec chaque événement de journal. Par conséquent, certains puits modifient le modèle de message en une EventTypevaleur numérique (par exemple 0x1234abcd) ou vous pouvez ajouter un enrichisseur au pipeline de journalisation pour le faire vous-même .

C'est plus subtile que la différence suivante, mais elle est extrêmement puissante lorsqu'il s'agit de traiter de gros volumes de journaux.

Données structurées

Toujours en considérant les deux événements relatifs à l'utilisation de l'espace disque, il peut être assez simple d'utiliser des journaux de texte pour interroger un utilisateur particulier like 'Disk quota' and like 'DTI-Matt'.

Mais les diagnostics de production ne sont pas toujours aussi simples. Imaginez qu'il soit nécessaire de trouver des événements où le quota de disque dépassé était inférieur à 125 Mo?

Avec Serilog, cela est possible dans la plupart des éviers en utilisant une variante de:

Quota < 125

Construire ce type de requête à partir d'une expression régulière est possible, mais cela fatigue vite et finit généralement par être une mesure de dernier recours.

Ajoutez maintenant à cela un type d'événement:

Quota < 125 and EventType = 0x1234abcd

Vous commencez à voir ici comment ces fonctionnalités se combinent de manière simple pour que le débogage de la production à l'aide de journaux ressemble à une activité de développement de premier ordre.

Un autre avantage, peut-être moins facile à éviter au début, mais une fois que le débogage de la production est sorti du domaine du piratage des expressions rationnelles, les développeurs commencent à valoriser davantage les journaux et à faire preuve de plus de soin et de considération lorsqu'ils les écrivent. De meilleurs journaux -> des applications de meilleure qualité -> plus de bonheur tout autour.

Lorsque vous collectez des journaux à des fins de traitement, que ce soit pour une analyse dans une base de données et / ou une recherche ultérieure dans les journaux traités, l’utilisation de la journalisation structurée simplifie / optimise une partie du traitement. L'analyseur peut tirer parti de la structure connue ( par exemple, JSON, XML, ASN.1) et utiliser des machines à états pour l'analyse, par opposition aux expressions régulières (dont la compilation et l'exécution peuvent coûter cher (relativement). L'analyse de texte de forme libre, telle que celle suggérée par votre collègue, a tendance à s'appuyer sur des expressions régulières et à ce que ce texte ne change pas . Cela peut rendre l' analyse syntaxique texte libre plutôt fragile ( à savoir l' analyse syntaxique est étroitement couplé au texte exact dans le code).

Considérons également le cas de recherche / consultation, par exemple :

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

LIKEles conditions nécessitent des comparaisons avec chaque textvaleur de ligne; Là encore, cela coûte relativement cher en calcul, en particulier lorsque des caractères génériques sont utilisés:

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

Avec la journalisation structurée, votre message de journal relatif aux erreurs de disque peut ressembler à ceci dans JSON:

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

Les champs de ce type de structure peuvent très facilement mapper, par exemple, les noms de colonne de table SQL, ce qui signifie que la recherche peut être plus spécifique / granulaire:

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

Vous pouvez placer des index sur les colonnes dont les valeurs doivent faire l'objet de recherches / recherches fréquentes, à condition de ne pas utiliser de LIKEclauses pour ces valeurs de colonnes . Plus vous divisez votre message de journal en catégories spécifiques, plus vous pouvez cibler votre recherche. Par exemple, en plus du error_typechamp / de la colonne dans l'exemple ci-dessus, vous pourriez même être "error_category": "disk", "error_type": "quota"ou être tel.

Plus structure que vous avez dans vos messages journaux, plus votre analyse syntaxique / systèmes de recherche (tels que fluentd, elasticsearch, kibana) peut tirer profit de cette structure, et d' effectuer leurs tâches avec une plus grande vitesse et moins de CPU / mémoire.

J'espère que cela t'aides!

La journalisation structurée ne vous apportera que peu d’avantages lorsque votre application créera quelques centaines de messages de journalisation par jour. Ce sera certainement le cas lorsque vous aurez quelques centaines de messages de journalisation par seconde provenant de nombreuses applications déployées différentes.

Dans le même ordre d'idées , la configuration dans laquelle les messages de journal se retrouvent dans la pile ELK convient également pour une mise à l'échelle dans laquelle la consignation en SQL devient un goulot d'étranglement.

J'ai vu la configuration de la "journalisation et de la recherche de base" avec SQL select .. likeet les expressions rationnelles poussées à l'extrême - il y a des faux positifs, des omissions, un code de filtre horrible avec des bogues connus qui est difficile à maintenir et que personne ne veut toucher, nouveaux messages de journalisation qui ne suivent pas les hypothèses du filtre, réticence à toucher les instructions de journalisation dans le code, de peur qu'ils ne cassent les rapports, etc.

Ainsi, plusieurs logiciels émergent pour mieux traiter ce problème. Il y a Serilog, j'ai entendu dire que l' équipe NLog était en train de l'examiner , et nous avons écrit StructuredLogging.Jsonpour Nlog . Je vois aussi que les nouvelles abstractions de journalisation ASP.Net "permettent aux fournisseurs de journalisation d'implémenter ... la journalisation structurée".

Un exemple avec StructuredLogging. Vous vous connectez à un enregistreur NLog comme ceci:

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

Ces données structurées vont à kibana. La valeur 1234est stockée dans le OrderIdchamp de l'entrée du journal. Vous pouvez ensuite effectuer une recherche à l'aide de la syntaxe de requête kibana, par exemple pour toutes les entrées de journal où @LogType:nlog AND Level:Error AND OrderId:1234.

Messageet ne OrderIdsont désormais plus que des champs dans lesquels il est possible de rechercher des correspondances exactes ou inexactes selon vos besoins ou d'agréger des nombres. C'est puissant et flexible.

Parmi les meilleures pratiques de StructuredLogging :

Le message enregistré doit être identique à chaque fois. Il doit s'agir d'une chaîne constante et non d'une chaîne formatée pour contenir des valeurs de données telles que des identifiants ou des quantités. Ensuite, il est facile de rechercher.

Le message consigné doit être distinct, c'est-à-dire différent du message généré par une instruction de journal non liée. Ensuite, sa recherche ne correspond pas non plus à des choses non liées.