Apprenez étape par étape à imprimer avec élégance les journaux de liens complets dans le nœud

Lorsqu'un utilisateur signale un problème : lorsqu'une erreur se produit lors de l'utilisation d'une certaine fonction en ligne, comment la localiser rapidement et avec précision ? Comment suivre efficacement l'optimisation lorsqu'une certaine interface de requête renvoie les données lentement ?

1. Principe et pratique

Comme nous le savons tous, lorsqu'une requête arrive, les journaux suivants seront probablement générés :

1. AceesLog : journal des accès utilisateur

2. Exception : journal des exceptions de code

3. SQL : journal des requêtes SQL

4. ThirdParty : tiers-

du service du parti

Comment suivre tous les journaux générés par une demande ?

L'approche générale consiste à utiliser un requestId comme identifiant unique,

puis à écrire un middleware pour injecter le requestId dans le contexte, lorsque la journalisation doit être effectuée, retirez-le du contexte pour l'imprimer

dans les services tiers et les journaux SQL

, vous devez également injecter le requestId dans le contexte. Le requestId est passé dans la fonction correspondante pour l'impression. Il est trop compliqué de le transmettre couche par couche, et le code est également relativement intrusif.

Notre objectif est de réduire le caractère intrusif du code, de l'injecter une seule fois et de le suivre automatiquement.

Après recherche, async_hooks peut suivre le cycle de vie du comportement asynchrone. Dans chaque ressource asynchrone (chaque requête est une ressource asynchrone), elle possède 2 ID,

à savoir asyncId (l'ID du cycle de vie actuel de la ressource asynchrone), trigerAsyncId (ressource asynchrone parent). IDENTIFIANT).

async_hooks fournit les hooks de cycle de vie suivants pour écouter les ressources asynchrones :

asyncHook = async_hook.createHook({
  //Écouter la création de ressources asynchrones init(asyncId,type,triggerAsyncId,resource){},
  // Avant que la fonction de rappel de ressource asynchrone ne commence à s'exécuter before(asyncId){},
  //Après le début de l'exécution de la fonction de rappel de ressource asynchrone, after(asyncId){},
  // Surveiller la destruction des ressources asynchrones destroy(asyncId){}
})

Ensuite, si nous effectuons un mappage, chaque asyncId est mappé à un stockage et le requestId correspondant est stocké dans le stockage, alors le requestId peut être facilement obtenu.

Il se trouve que la bibliothèque cls-hooked a été encapsulée sur la base de async_hooks, conservant une copie des données dans la même ressource asynchrone et la stockant sous la forme de paires clé-valeur. (Remarque : async_hooked doit être utilisé dans une version supérieure de node>=8.2.1) Bien sûr, il existe d'autres implémentations dans la communauté, telles que cls-session, node-continuation-local-storage, etc.

Parlons d'un exemple d'utilisation de cls-hooked dans mon projet :

/session.js Créer un espace de stockage nommé

const createNamespace = require('cls-hooked').createNamespace 
const session = createNamespace('requestId-store') 
module.exports = session

/logger.js journal d'impression

const session = require('./session') 
module.exports = { 
infos : (message) => 
{ 
const requestId = session.get('requestId')
console.log(`requestId:${requestId}`, message) 
}, 
erreur : (message) => 
{ 
const requestId = session.get('requestId') 
console.error(`requestId:${requestId}`, message) 
} 
}

/sequelize.js sql appelle logger pour imprimer les journaux

const logger = require("./logger") 
nouveauSequelize( 
journalisation : fonction (sql, costtime) { 
logger.error( `sql exe : ${sql} | costtime ${costtime} ms` ); 
} )

/app.js Définissez requestId, définissez requestId pour renvoyer l'en-tête de réponse et imprimez le journal d'accès

const session = require('./session') 
const enregistreur = require('./logger') 
fonction asynchrone accessHandler (ctx, suivant) 
{ 
const requestId = ctx.header['x-request-id'] ||
const params = ctx.request.body ? JSON.stringify(ctx.request.body) : JSON.stringify(ctx.request.query)
//Définir requestId session.run(() => { session.set('requestId', requestId)
logger.info(`url:${ctx.request.path}; params:${params}`) next()
//Définit l'en-tête de réponse de retour ctx.res.setHeader('X-Request-Id',requestId)
}) }

Regardons le journal lorsqu'un chemin de requête est /home?a=1 :

Journal d'accès :
ID de demande : 79f422a6-6151-4bfd-93ca-3c6f892fb9ac url :/home;params :{"a":"1"}

Journal SQL :
ID de demande : 79f422a6-6151-4bfd-93ca-3c6f892fb9ac exe sql :
Exécuté (par défaut) : SELECT `id` FROM t_user

Vous pouvez voir que le requestId du journal de l'intégralité du lien pour la même requête est le même. Si une alarme est envoyée ultérieurement à la plateforme d'alarme, nous pouvons alors trouver l'intégralité du lien exécuté par cette requête en fonction du requestId.

Les étudiants attentifs remarqueront peut-être que j'ai également défini le requestId dans l'en-tête de réponse renvoyé par l'interface. Le but est que si une requête répond lentement ou présente des problèmes, le requestId peut être connu directement depuis le navigateur et analysé.

2. Surcharge de performances :

j'ai effectué un test de résistance localement.

Voici la comparaison de l'utilisation de la mémoire :

Environ 10 % de plus que de ne pas utiliser async_hook.

C'est correct pour notre système QPS avec un système à 100 niveaux, mais s'il s'agit d'un service hautement simultané, nous devrons peut-être l'examiner attentivement.

ps : S'il y a des erreurs, veuillez les signaler. Si vous ne les aimez pas, veuillez ne pas commenter.