Como debugar nossas aplicações em NodeJS com mais eficiência!

Neste post vou falar um pouco de como podemos usar o Chrome Devtools para debugar nossas aplicações em NodeJS e como podemos usar os logs a o nosso favor.

O que vamos abordar neste post:

Fazendo debug de aplicações em NodeJS usando o Chrome Devtools
Agora vamos falar um pouco sobre Logs!
Lembrando de funções básicas de log
Boas ferramentas!
Dicas

Fazendo debug de aplicações em NodeJS usando o Chrome Devtools

A partir da versão 6.3.0 do NodeJS temos disponível a flag — inspect que disponibiliza para nós uma porta específica para debug via conexão socket, isso possibilita que nossas aplicações em NodeJS sejam analisadas usando o Chrome Devtools e todos seus recursos mais legais. Para saber mais sobre esse protocolo e como podemos usar ele não só com o Chrome Devtools sugiro que leiam o documento Chrome Debugging Protocol Viewer.

Vamos da uma olhada como isso funciona de uma forma simples com alguns exemplos.

O código a seguir simplesmente calcula quantos anos você estaria a 10 anos atrás e quantos anos você vai estar daqui a 10 anos.

O código está separado em 3 arquivos, future.js, past.js e index.js, segue a baixo:

future.js

const future = (age, gap) => {
  return `In ${gap} years you will be ${Number(age)+gap}<br/>`;
}

module.exports = future;

past.js

const past = (age, gap) => {
  return `${gap} years ago you were ${Number(age)-gap}<br/>`;
};

module.exports = past;

index.js

const express = require('express');
const past = require('./past');
const future = require('./future');

const app = express();

app.get('/:age', (req, res) => {
  res.send(past(req.params.age, 10) + future(req.params.age, 10));
});

app.listen(3000);

Executando esse app e acessando a url: http://localhost:3000/30 temos o seguinte resultado:

Podemos ver que a um resultado não esperado “NaN”, vamos usar o Chrome Devtools para tentar achar o problema. Para fazermos isso temos que iniciar nosso app com a flag — inspect ficando assim:

$ node — inspect index.js

Podemos notar que na saída do console vamos ter algo parecido com:

Debugger listening on ws://127.0.0.1:9229/60b72ae3–68ce-4123-bab4-cf8d2e180df6
For help, see: https://nodejs.org/en/docs/inspector

Isso quer dizer que nosso debug está funcionando e pronto para ser conectado a um cliente via socket com essa url:

ws://127.0.0.1:9229/60b72ae3–68ce-4123-bab4-cf8d2e180df6

Para se conectar a ele vamos abrir uma nova aba do Chrome e digitar o seguinte endereço: "chrome://inspect", se tudo der certo já podemos ver que o Devtools encontrou nosso app.

Para iniciar nosso Devtools vamos clicar em “Open dedicated DevTools for Node” e então podemos ver nosso Devtools aberto:

Vamos focar agora em descobrir o que está de errado no nosso app que está retornando o valor “NaN”, de início vamos colocar um breakpoint na linha 8 e fazer um novo request para nosso app na url "http://localhost:3000/30", no navegador a página deve se manter esperando pelo nosso server já que temos um breakpoint interrompendo a continuidade da execução, no nosso devtools podemos ver que a linha com o breakpoint ficou destacada:

Podemos notar algumas coisas interessantes aqui, uma delas é que se passamos o mouse sobre a variável req.params podemos ver os valores que estão chegando na nossa request, com base nisso já podemos descobrir a causa no nosso problema mas vamos continuar dando uma olhada.. Na coluna à direita podemos ver toda call stack que foi chamada até o momento, e no início da coluna temos alguns controles que podem ser muito úteis no nosso debug, vamos clicar no terceiro botão de controle para seguir um passo à frente na execução do nosso programa.

Feito isso vamos entrar no próximo passo da execução do nosso programa que nesse caso é a função past como podemos ver na imagem a seguir:

Passando o mouse sobre as variáveis/parâmetros podemos conferir se todos os valores estão chegando corretamente, uma outra forma de ver isso é olhando na coluna à direita em baixo da Call Stack temos uma parte chamada Scope -> Local aí podemos ver todas as variáveis do escopo local no momento e seus respectivos valores, veja a imagem abaixo:

Certo, conferindo que aqui está tudo ok vamos voltar para a função principal no arquivo index clicando no quarto botão de controle (setinha para cima).

Voltando para o arquivo index podemos notar que a função future na linha 8 agora está destacada, isso quer dizer que ela será a próxima na execução, então se a gente clicar no terceiro botão de controle novamente indo para a próxima execução do nosso programa vamos cair no arquivo future.js na função future como mostrado na imagem abaixo:

Passando o mouse pelas variáveis/parâmetros podemos notar que o parâmetro age está com o valor undefined (podemos ver também no Scope -> Local na coluna a direita), ou seja ele está recebendo um valor undefined mas o problema não está nesta função, vamos voltar novamente para função principal no arquivo index.js clicando no quarto botão de controle (setinha para cima).

No arquivo index.js passando o mouse pelo parâmetro que é passado para a função future podemos notar que realmente está undefined e se observarmos com mais atenção podemos ver que está errada por não existir o parâmetro future req.params.future o correto seria req.params.age, podemos editar isso direto no devtools ou na sua IDE de preferência. Fazendo essa correção vamos remover o breakpoint e clicar no botão azul (primeiro botão de controle) para dar continuidade na execução do nosso programa. Feito isso podemos notar que no navegador os valores já vão estar corretos. Pronto! Problema resolvido.

O exemplo mostrado aqui é bem simples mas existem diversos outros recursos no Devtools que pode nos ajudar a debugar nossa aplicação de uma forma bem completa como o uso de memória e cpu, como descobrir gargalos de memória, como podemos aproveitar a Call Stack para entender como nossa aplicação está funcionando e etc.

Para um exemplo mais aprofundado pode da uma olhada nesse post Finding And Fixing Node.js Memory Leaks: A Practical Guide

Podemos usar esse recurso do — inspect para debugar aplicações que estão rodando em container também, para saber mais sugiro dar uma olhada nesse post How to Debug a Node.js app in a Docker Container

Podemos também usar esse recurso em produção mas isso é extremamente perigoso já que abre uma porta direto com sua aplicação e todo seu contexto, se realmente for necessario usar isso em produção sugiro que siga essa recomendação Node Doc, remote debugging scenarios

Algumas curiosidades de como tudo isso funciona

Tudo isso é possível graças a engine JavaScript V8, quando executamos o node com a flag — inspect a engine V8 abre uma porta que aceita conexão WebSocket, uma vez que a conexão é feita comandos em formato de pacotes JSON são enviados entre o Inspector e o cliente.
O Inspector WebSocket é escrito em C e roda em uma thread separada assim quando o processo é pausado (breakpoint) o inspector continua funcionando.
Quando um breakpoint é colocado o event loop é pausado e toda informação (Call Stack, Variáveis) daquele momento são enviadas para o cliente, cada interação com os botões de controle é despausado o event loop e pausado novamente atualizando essas informações no cliente.

Agora vamos falar um pouco sobre Logs!

Logs no STDOUT

Quando estamos executando nosso programa e algo dá errado um log de erro é mostrado no nosso STDOUT como esse:

Mas se precisamos ver um trace maior do que é mostrada por padrão? Para isso podemos usar a flag -stack-trace-limit=21 para alterar o limite de trace da saída para um valor que for melhor para nós, exemplo:

Uso da env DEBUG

Outro recurso legal que podemos aproveitar é usar o máximo o debug do node, por exemplo, podemos habilitar o debug do node para nos mostrar todo log de execução que está acontecendo no express, para isso vamos executar o node com a flag DEBUG=express:*.

DEBUG=express:* node index.js

Como a imagem acima nos mostra essas informações podem ser úteis para uma investigação mais aprofundada do que está acontecendo na aplicação.

Se eu quiser saber o log só do express router por exemplo:

DEBUG=express:router node index.js

Para mostra tudo:

DEBUG=* node index.js

Lembrando de funções básicas de log

console.log(arguments): printa algo na saída padrão
console.error(arguments): printa algo na saída de erro
console.trace(label): printa um trace da execução
console.time(label) / console.timeEnd(label): essa combinação pode ser usada para mostrar o tempo de execução de uma parte do código.
console.dir(object): printa a estrutura de um objeto na saída padrão

Para aproveitar a o máximo todo o poder que os logs podem fornecer nos momentos em que mais precisamos não podemos deixar de lado os bons padrões para se ter em um log, já existem vários desses padrões muito bem definidos na comunidade e um que recomendo a análise é a do Twelve-Factor App Logs.

Dicas

Não se esqueça dos testes

Os testes podem ajudar a ampliar o entendimento da sua aplicação facilitando assim achar o motivo de um possível bug, lembre sempre de olhar seus testes em um processo de debug e melhorar ainda escrever o teste para a caso em questão ajudando assim que o mesmo problema não retornar futuramente.

Aproveite a evn NODE_DEBUG em seu localhost

Você pode usar essa env para um “scan” do que está acontecendo na sua aplicação em tempo de execução separadamente por módulos do node por exemplo, module, http e etc.
Para mais informações: node_debug

Tome cuidado com a forma que você está fazendo seus logs

Para finalizar gostaria de recomendar uma palestra que mostra o impacto em desempenho que os logs podem ter na sua aplicação em especial quando usamos alguma lib de log, Node Summit 2016 — The Cost of Logging.

Boas ferramentas!

stackup: É um módulo do npm que enriquece as informações de erro quando algo dá errado, ele é bem útil principalmente quando algo dá erro em chamada async. Saiba mais em: https://www.npmjs.com/package/stackup

Conclusão

Bom espero que esse post possa te auxiliar em fazer cada vez mais debugs de forma eficiente ajudando a solucionar os problema que nos deparamos no dia a dia sem bater muita a cabeça.

Fonts:

Stay hungry Stay foolish!

Blog