Ensine passo a passo como imprimir logs de link completo no nó com elegância

Quando um usuário relata um problema: Quando ocorre um erro ao usar uma determinada função online, como ele pode ser localizado com rapidez e precisão? Como rastrear efetivamente a otimização quando uma determinada interface de solicitação retorna dados lentamente?

1. Princípio e prática

Como todos sabemos, quando chega uma solicitação, provavelmente serão gerados os seguintes logs:

1. AceesLog: log de acesso do usuário

2. Exceção: log de exceção de código

3. SQL: log de consulta sql

4. ThirdParty: terceiro-

de serviço de terceiros

Como rastrear todos os logs gerados por uma solicitação?

A abordagem geral é usar um requestId como um identificador exclusivo

e, em seguida, escrever um middleware para injetar o requestId no contexto. Quando o registro precisar ser feito, retire-o do contexto para impressão

em serviços de terceiros e logs SQL

, você também precisa injetar o requestId no contexto. O requestId é passado para a função correspondente para impressão. É muito problemático passá-lo camada por camada e o código também é relativamente intrusivo.

Nosso objetivo é reduzir a intrusividade do código, injetá-lo uma vez e rastreá-lo automaticamente.

Após a pesquisa, async_hooks pode rastrear o ciclo de vida do comportamento assíncrono. Em cada recurso assíncrono (cada solicitação é um recurso assíncrono), ele possui 2 IDs,

ou seja, asyncId (o ID do ciclo de vida atual do recurso assíncrono), trigerAsyncId (recurso assíncrono pai). EU IA).

async_hooks fornece os seguintes ganchos de ciclo de vida para escutar recursos assíncronos:

asyncHook = async_hook.createHook({
  //Ouvir a criação de recursos assíncronos init(asyncId,type,triggerAsyncId,resource){},
  // Antes que a função de retorno de chamada do recurso assíncrono comece a ser executada before(asyncId){},
  //Depois que a função de retorno de chamada do recurso assíncrono começar a ser executada, after(asyncId){},
  // Monitore a destruição de recursos assíncronos destroy(asyncId){}
})

Então, se fizermos um mapeamento, cada asyncId mapeia para um armazenamento e o requestId correspondente é armazenado no armazenamento, então o requestId pode ser facilmente obtido.

Acontece que a biblioteca cls-hooked foi encapsulada com base em async_hooks, mantendo uma cópia dos dados no mesmo recurso assíncrono e armazenando-os na forma de pares chave-valor. (Nota: async_hooked precisa ser usado em uma versão superior do node>=8.2.1) Claro, existem outras implementações na comunidade, como cls-session, node-continuation-local-storage, etc.

Vamos falar sobre um exemplo de uso de cls-hooked em meu projeto:

/session.js Crie um espaço de armazenamento nomeado

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

/logger.js imprimir log

const session = require('./session') 
módulo.exportações = { 
informações: (mensagem) => 
{ 
const requestId = session.get('requestId')
console.log(`requestId:${requestId}`, mensagem) 
}, 
erro: (mensagem) => 
{ 
const requestId = session.get('requestId') 
console.error(`requestId:${requestId}`, mensagem) 
} 
}

/sequelize.js sql chama o logger para imprimir logs

const logger = require("./logger") 
novoSequelize( 
registro em log: função (sql, costtime) { 
logger.error(`sql exe: ${sql} | costtime ${costtime} ms` ); 
} )

/app.js Defina requestId, defina requestId para retornar o cabeçalho de resposta e imprima o log de acesso

const session = require('./session') 
const registrador = require('./logger') 
função assíncrona accessHandler(ctx, next) 
{ 
const requestId = ctx.header['x-request-id'] ||
const params = ctx.request.body? JSON.stringify(ctx.request.body): JSON.stringify(ctx.request.query)
//Definir requestId session.run(() => { session.set('requestId', requestId)
logger.info(`url:${ctx.request.path}; params:${params}`) next()
//Definir o cabeçalho de resposta de retorno ctx.res.setHeader('X-Request-Id',requestId)
}) }

Vejamos o log quando o caminho da solicitação é /home?a=1:

Log de acesso:
requestId:79f422a6-6151-4bfd-93ca-3c6f892fb9ac url:/home;params:{"a":"1"}

Registro SQL:
requestId:79f422a6-6151-4bfd-93ca-3c6f892fb9ac sqlexe:
Executado (padrão): SELECT `id` FROM t_user

Você pode ver que o log requestId de todo o link para a mesma solicitação é o mesmo. Se houver um alarme enviado posteriormente para a plataforma de alarme, podemos encontrar todo o link executado por esta solicitação com base no requestId.

Alunos cuidadosos podem notar que eu também defini o requestId no cabeçalho de resposta retornado pela interface. O objetivo é que, se uma solicitação responder lentamente ou tiver problemas, o requestId possa ser conhecido diretamente do navegador e analisado.

2. Sobrecarga de desempenho:

fiz um teste de estresse localmente.

Esta é a comparação do uso de memória:

Cerca de 10% a mais do que não usar async_hook.

Não há problema em nosso sistema QPS com sistema de 100 níveis, mas se for um serviço altamente simultâneo, talvez seja necessário considerá-lo com cuidado.

ps: Se houver algum erro, aponte-o. Se não gostar, não comente.