Minimiser les problèmes de production grâce à la traçabilité des logs

Plantons le décor :

Un incident critique s'est produit dans la production. C'est à vous vous de le trouver et de le résoudre. Vous examinez les journaux d'une centaine de services différents et vous êtes totalement perdu. Quelle action a provoqué quelle réaction ? L'erreur est-elle liée à cet appel API ou à cet autre ? Nous sommes tous passés par là. Et nous sommes tous d'accord pour dire que ce n'est pas amusant.

Mais il y a une une solution. Une solution qui ne résoudra pas tous vos problèmes de production, mais qui vous aidera considérablement. Et la bonne nouvelle, c'est qu'elle peut être facilement intégrée à vos services.

Traçage du journal.

Cela semble simple, n'est-ce pas ? Mais en réalité, il peut s'agir d'un outil puissant pour presque tous les types d'enquêtes. En effet, dans les architectures modernes actuelles, lorsqu'un utilisateur appuie sur un simple bouton de notre site, il envoie une requête API à la passerelle API, à un service métier, à une base de données, à un autre service, à un bus de messages centralisé, à un autre service, et ainsi de suite.

C'est un voyage accablant qui est inondé de centaines de journaux produits par chaque flux qui se produit des centaines de fois par seconde par des centaines de milliers d'utilisateurs. C'est un vrai casse-tête.

Qu'entendez-vous par "traçage du journal" ?

Avant de passer à la mise en œuvre de ces concepts, il convient de comprendre ce que l'on entend par traçage des journaux. Tracer signifie généralement ajouter un identifiant qui peut être utilisé pour agréger des données. La signification de chaque identifiant est alors une question de goût. Nous pouvons avoir un identifiant de traçage qui est ajouté à toutes les données dans une seule requête. Nous pouvons aussi avoir un ensemble d'identifiants qui seront utilisés dans le contexte d'un seul service. L'idée de base est la suivante :

basic log tracing flow

Il y a deux concepts clés à comprendre :

1. Agréger tous les journaux de tous les services pour chaque demande via le traçage

2. Laisser l'infrastructure s'occuper du traçage afin qu'il n'interfère pas avec la logique de l'entreprise.

Alors, comment la mettre en œuvre ?

Regroupement des journaux pour chaque demande

Ce concept est assez simple. Nous devons suivre deux règles très simples :

• Ajouter l'ID de la trace à chaque journal que nous écrivons pour une requête et transmettre l'ID de la trace chaque fois que nous effectuons des opérations d'entrée-sortie.

• Si deux services communiquent sur la même requête via un bus de messages, nous ajouterons l'ID de la trace au message ajouté au bus. Si deux services communiquent via des requêtes http, nous ajouterons l'identifiant de la trace aux en-têtes de la requête. De cette manière, nous pouvons suivre une requête unique tout au long de son déroulement sans être dérangés par d'autres requêtes ou journaux se produisant en parallèle.

Séparation de la logique commerciale et de l'infrastructure

Assurer le suivi de toutes les données envoyées ou reçues peut nécessiter une bonne dose de codage. Nous voulons toujours séparer autant que possible les concepts d'infrastructure de ce type de la logique d'entreprise. Heureusement, dans notre cas, il est facile de séparer presque entièrement la gestion du traçage.

Dans notre code, nous écrivons des journaux pour divers événements et erreurs tout en ajoutant des données à ces journaux. Nous voulons garder ces flux intacts tout en ajoutant notre traçage à tous les journaux en parallèle. La plupart des outils que nous utilisons aujourd'hui nous permettent d'ajouter des intercepteurs à chaque requête qu'ils reçoivent. Si nous nous assurons d'ajouter des intercepteurs à notre outil IO et à notre outil de journalisation, nous sommes sur la bonne voie pour garantir que tous les journaux seront tracés sans toucher au code existant.

La façon la plus simple de l'expliquer est de montrer un exemple concret tiré de nos propres services.

Le code ci-dessous provient du service nodejs qui reçoit des requêtes http, écrit plusieurs logs et fait ensuite une requête http au service suivant. C'est l'un des trois endroits où nous avons placé des intercepteurs : requête entrante, journalisation et requête sortante.

function tracingMiddleware(req,res,next) {
    ns.run(() => {
        let traceId = req.headers['x-b3-traceid'];
        let spanId = req.headers['x-b3-spanid'];
        if (!traceId || !spanId) {
            traceId = uuid().replace(/-/g, '');
            spanId = uuid().replace(/-/g, '').substring(16);
        }
        ns.set('traceId', traceId);
        ns.set('spanId', spanId);
        next();
    });
}

Nous utilisons Express comme infrastructure d'API pour mettre en œuvre des middlewares qui interceptent chaque demande. Nous extrayons l'identifiant de la demande ou en créons un nouveau si nous sommes le premier service de la chaîne. Nous définissons ensuite l'identifiant de trace dans un outil de stockage de session afin de pouvoir le récupérer à chaque étape du processus.

Notez que le ns.set. Il s'agit de l'utilisation de cls-hookedun paquetage de stockage local continu qui englobe les hooks asynchrones des nœuds. Il nous permet de stocker localement l'identifiant de la trace pour chaque session. Mais si vous utilisez Node 14, cette fonctionnalité est déjà intégrée avec async local storage. Ce qui est intéressant avec cette méthode, c'est qu'elle peut être implémentée dans n'importe quel langage.

Nous ajoutons ensuite un intercepteur à l'outil de journalisation qui récupère l'identifiant de la session et l'ajoute à chaque ligne de journal :

function createBunyanStreamMiddleware(streams) {
    return {
        type: 'raw',
        level: process.env.LOG_LEVEL,
        stream: {
            write: (entry) => {
                if(ns && ns.active) {
                    entry['traceId'] = ns.get('traceId');
                    entry['spanId'] = ns.get('spanId');
                }
                streams.forEach((stream) => {
                        stream.stream.write(entry)
                });
            }
        }
    }
}

Enfin, nous ajoutons un intercepteur à l'outil http qui ajoute l'identifiant de la trace aux en-têtes de la requête avant que celle-ci ne soit envoyée :

function insertTracingHeaders(config = {}){
    if(ns && ns.active) {
        const traceId = ns.get('traceId');
        const spanId = ns.get('spanId');
        if (!config.headers) {
            config.headers = {};
        }
        if (traceId && spanId) {
            config.headers['x-b3-parentspanid'] = spanId;
            config.headers['x-b3-traceid'] = traceId;
        }
    }
    return config;
}

L'ensemble du flux ressemblera à ceci :

tracing flow with interceptors

En conclusion

Le traçage des journaux peut être utilisé dans toutes sortes de contextes, mais cette utilisation particulière permet d'éviter bien des maux de tête lors de la recherche d'erreurs. Il permet de s'assurer que les journaux de requêtes de chaque flux sont facilement accessibles, de sorte que vous n'avez pas besoin de fouiller dans des milliers de journaux sans rapport les uns avec les autres.

Nous pouvons dire personnellement que dans les services où nous avons appliqué ces concepts, l'efficacité et la valeur ajoutée de l'investigation des logs ont grimpé en flèche. Depuis lors, passer au crible les journaux d'une autre manière n'est tout simplement pas satisfaisant.

Ainsi, la prochaine fois qu'un incident critique se produira en production et qu'il vous appartiendra de le résoudre, au moins cette fois-ci, les journaux seront de votre côté.