ch04.3-capturing-metadata.md

Capturando metadados

O código de todo o capítulo pode ser encontrado no diretório code/chapter_04.3

O Logger está gravando no arquivo como esperado, mas há um problema: não está capturando nenhum metadado útil. Aqui está um exemplo de como nossos logs estão atualmente:

Hello this is a log of type ERROR

Isso não difere em nada de usar o método console.log padrão. Por exemplo, poderíamos escrever:

const logger = /* init logger */

function create_subscription() {
    const my_log_message = 'This is an error'
    logger.error(`[Error]: create_subscription() Line No. 69 ${my_log_message}`);       
}

Esse código parece funcionar. Porém, se você adicionar mais funcionalidades acima dessa função no mesmo arquivo, o número da linha mudará de novo e de novo, o que não é o ideal.

Para uma biblioteca de logging, é importante minimizar a quantidade de código desnecessário que os clientes precisar digitar. Deveríamos realizar o trabalho pesado para nossos clientes para que eles só precisem chamar o método logger.error (ou outro similar).

Isso vai tornar nossa biblioteca mais fácil de usar e mais amigável.

function my_deeply_nested_api_route() {
    logger.error('my error')
    logger.warn('my warning')
}

A saída do código acima deveria ficar assim:

[2023-08-19T15:10:37.097Z] [ERROR]: my_deeply_nested_api_route (/Users/ishtmeet/Code/logtar/test.js:12) my error
[2023-08-19T15:10:37.097Z] [ERROR]: my_deeply_nested_api_route /Users/ishtmeet/Code/logtar/test.js:13 my warning

O quão legal seria atingir essa funcionalidade com um pouco de hack em Javascript?

Antes de mergulharmos nos detalhes de como podemos extrair o nome da função ou o número da linha, vamos dar uma pequena pausa para entender o que é uma pilha de chamadas. Mas antes de entender o que é uma pilha de chamadas, precisamos entender o que é uma pilha.

O que é uma Pilha?

Uma pilha é uma estrutura de dados amplamente utilizada na programação. É feita para armazenar uma coleção de elementos e baseada no princípio Last In First Out (LIFO). Isso significa que o elemento mais recente adicionado à pilha é o primeiro a ser removido.

Pilhas são utilizadas em uma variadade de aplicações, desde lidar com chamadas de função até desfazer/refazer ações em aplicativos de software. Pilhas também podem ser implementadas de diferentes maneiras, como por exemplo, utilizando arrays ou listas ligadas.

Exemplos de Pilhas

Pilhas são uma ocorrência comum no dia a dia e aqui estão alguns exemplos:

• Uma pilha de livros
• Uma pilha de arquivos
• Uma pilha de pizzas

Em cada um desses casos, o item mais recente é colocado no topo da pilha enquanto os itens mais antigos estão localizados embaixo. Por exemplo, para acessar a pizza debaixo, você vai precisar remover todas as pizzas acima dela na pilha.

A Pilha de Chamadas

Uma pilha de chamadas é um tipo especial de pilha que monitora chamadas de função. Sempre que uma função é chamada, sua informação é empurrada para pilha de chamadas. Quando a função retorna, a informação é retirada da pilha.

Aqui está um exemplo de uma pilha de chamadas no JavaScript:

function add(a, b) {
  return a + b;
}

function multiply(a, b) {
  return a * b;
}

function calculate() {
  const x = 10;
  const y = 5;

  const result1 = add(x, y);
  const result2 = multiply(add(1, 2), result1);

  return result2;
}

calculate();

No exemplo apresentado, a função calculate chama outras duas funções (add e multiply). Cada vez que uma função é chamada, a informação é adicionada à pilha de chamadas. Quando uma função retorna, sua informação é removida da pilha de chamadas.

Para ilustrar melhor isso, considere o gráfico a seguir:

Quando a função calculate é chamada, sua informação é adicionada no topo da pilha. A função então chama a função add, que tem sua informação adicionada no topo da pilha. Então, a função add retorna e sua informação é removida da pilha. A função multiply é então chamada e sua informação é adicionada no topo da pilha.

Uma coisa importante a ser notada é, quando multiply é chamada, o primeiro argumento é uma chamada para add(1, 2). Isso significa que precisamos colocar add(..) de volta na pilha, em cima de multiply na pilha de chamadas. Quando add finalizar sua execução, será removida do topo.

Esse processo continua, com cada chamada de função adicionando sua informação no topo da pilha e retornando, tendo sua informação sendo removida do topo da pilha.

Essa pilha de chamadas é importante porque permite que o programa se mantenha a par de onde está a sua execução. Se uma chamada de função não é apropriadamente removida da pilha, isso pode causar um erro de stack overflow, o que pode quebrar o programa.

Em linguagens compiladas como C++ ou Rust, o compilador é esperto o suficiente para incorporar a função add() acima, colocando diretamente o conteúdo da função add() no lugar da chamada de função. Isso pode resultar em melhorias de performance por eliminar a sobrecarga de chamadas e retornos de funções.

Obtendo Informações da Pilha

Mas como vemos essa pilha? Bem, não é tão difícil. Quando você lança (throw) um erro, aquele erro contém informações sobre a pilha.

function main() { child(); }

function child() { grand_child(); }

function grand_child() { 
    throw new Error('This is an error from grand_child()');
}

main()

Se você executar esse arquivo usando node nome_do_arquivo.js, ele exibe isso no console

Error: This is an error from grand_child()
    at grand_child (/Users/ishtmeet/Code/logtard/test.js:10:11)
    at child (/Users/ishtmeet/Code/logtard/test.js:6:5)
    at main (/Users/ishtmeet/Code/logtard/test.js:2:5)
    at Object.<anonymous> (/Users/ishtmeet/Code/logtard/test.js:12:1)
    at Module._compile (node:internal/modules/cjs/loader:1198:14)
    ...

Precisamos nos preocupar apenas com as 5 primeiras linhas. O resto delas, são do mecanismo interno de execução de arquivos do Node.js. Vamos passar pelo erro acima linha por linha:

• A primeira linha inclui a mensagem de erro "This is an error from grand_child()", que é a mensagem personalizada fornecida por nós quando usamos a declaração throw na função grand_child().

• A segunda linha do rastreio de pilha indica que o erro foi originado na função grand_child(). O erro ocorreu na linha 10 e coluna 11 do arquivo test.js. Isso é onde a declaração throw está localizada dentro da função grand_child(). Por isso, grand_child estava no topo da pilha quando o erro foi encontrado.

• A terceira linha mostra que o erro ocorreu na linha 6 e coluna 5 do arquivo test.js. Essa linha marca onde a função grand_child() é chamada dentro da função child(). É isso que significa a função child() ocupando o segundo lugar na pilha de chamadas, atrás de grand_child().

• A quarta linha nos diz que a função child() foi chamada de dentro da função main(). O erro ocorreu na linha 2 e coluna 5 do arquivo test.js.

• A 5º linha nos diz que a função main() foi chamada do nível superior do script. Essa parte anônima do rastreio de pilha indica onde a execução do script começa. O erro ocorreu na linha 12 e coluna 1 do arquivo test.js. Isso é de onde a função main() é chamada diretamente no script.

Isso é chamado de rastreio de pilha. A declaração throw new Error() imprime o rastreio de pilha inteiro, que retrocede através da série de chamadas de funções que foram realizadas levando ao ponto onde o erro ocorreu. Cada chamada de função é gravada na ordem reversa, começando da função que causou diretamente o erro e retornando de volta ao ponto de entrada inicial do script.

Esse rastro de chamadas de funções, acompanhado dos seus caminhos de arquivo correspondentes e números de linha, fornecem aos desenvolvedores uma trilha clara a ser seguida. Ajuda a identificar onde e como o erro se originou.

Isso é exatamente o que queremos saber, de onde o logger.error e os outros métodos estavam sendo chamados.

Obtendo o nome da chamada e o número da linha

Como podemos usar a informação acima para obter o número da linha do código do cliente? Você consegue imaginar?

Vamos adicionar o seguinte conteúdo ao nosso método #log da classe Logger:

// file: lib/logger.js

class Logger {
    ...

    async #log(message, log_level) {
        if (log_level < this.#config.level || !this.#log.file_handle.fd) {
            return;
        }

        /* Novo código inserido */
        let stack_trace;
        try {
            throw new Error();
        } catch(error) {
            stack_trace = error.stack;
        }
        console.log(stack_trace)
        /* Fim do novo código */

        await this.#log_file_handle.write(log_message);
    }

    ...
}

Tente executar o arquivo test.js

// file: test.js

const {Logger} = require('./index')

async function initialize() {
    const logger = Logger.with_defaults();
    await logger.init();
    return logger;
}

async function main() {
    let logger = await initialize()
    logger.critical('Testing')
}

main()

Isso exibe

Error
    at Logger.#log (/Users/ishtmeet/Code/logtard/lib/logger.js:98:19)
    at Logger.critical (/Users/ishtmeet/Code/logtard/lib/logger.js:141:18)
    at main (/Users/ishtmeet/Code/logtard/test.js:12:12)

Sensacional. Sabemos quem invocou a função. Há 4 linhas. A parte importante está na última linha.

at main (/Users/ishtmeet/Code/logtard/test.js:12:12)

Aqui é onde chamamos logger.critical('Testing'). Porém, você pode pensar - "Tudo bem, é sempre a última linha". Não, não é. Vamos adicionar duas funções aninhadas no test.js

// file: test.js

...

async function main() {
    let logger = await initialize()
    nested_func(logger)
}

function nested_func(logger) {
    super_nested(logger)
}

function super_nested(logger) {
    logger.critical('Testing')
}

...

Depois de executar node test.js obtemos a seguinte saída.

Error
    at Logger.#log (/Users/ishtmeet/Code/logtard/lib/logger.js:98:19)
    at Logger.critical (/Users/ishtmeet/Code/logtard/lib/logger.js:141:18)
    at super_nested (/Users/ishtmeet/Code/logtard/test.js:20:12)
    at nested_func (/Users/ishtmeet/Code/logtard/test.js:16:5)
    at main (/Users/ishtmeet/Code/logtard/test.js:12:5)

No entanto, dessa vez, há mais duas linhas. Se você ler o rastreio de pilha de baixo para cima, você pode entender a sequência de passos que levaram ao erro. A informação mais útil na verdade não está na parte mais baixa, mas na quarta linha (incluindo a linha "Error" no topo do rastreio da pilha).

at super_nested (/Users/ishtmeet/Code/logtard/test.js:20:12)

A 4º linha será sempre a que invocou o método. Que é a linha diretamente abaixo da chamada para Logger.critical. Não é disso que precisamos?

Uma forma mais ergonômica

Olhando para o código que acabamos de escrever no método Logger.#log, ele aparenta estar mal escrito, tornando difícil de entender o resultado desejado. Além disso, porque estamos lançando um Error? Alguém que não esteja familiarizado com nosso código pode considerar isso redundante e remover.

Podemos tornar isso ainda melhor criando um método utilitário que extrai a informação essencial do nosso rastreio de pilha.

Adicione uma nova função no arquivo lib/utils/helpers.js

// file: lib/utils/helpers.js

function get_caller_info() {

}

module.exports = {
    check_and_create_dir,
    get_log_caller // Adicione isso!
}

Vamos obter o nosso rastreio de pilha de uma maneira mais curta e eficiente. Aqui está o que vamos fazer

// file: lib/util/helpers.js

function get_caller_info() {
    const error = {};
    Error.captureStackTrace(error);

    const caller_frame = error.stack.split("\n")[4];

    const meta_data = caller_frame.split("at ").pop();
    return meta_data
}

O Error.captureStackTrace(targetObject) é um método estático da classe Error, que é utilizado para customizar ou aprimorar a criação de rastreios de pilha ao lançar erros. Ele não lança um erro em si, mas modifica o objeto alvo para incluir um rastreio de pilha personalizado.

É feito especificamente para capturar rastreios de pilha sem gerar um objeto de erro completo, o que pode ser útil quando você quer criar seus objetos de erro personalizados e ainda capturar o rastreio de pilha de maneira eficiente. Ele associa diretamente o rastreio de pilha ao objeto fornecido.

const caller_frame = error.stack.split("\n")[4];

Estamos extraindo a 5º linha do rastreio de pilha. Repare, é a 5º linha e não a 4º como falamos na seção anterior. Isso é porque introduzimos mais uma função get_log_caller, que também estará presente na pilha de chamadas. Você pode imaginar uma pilha de chamadas como essa:

get_caller_info
Logger.#log
Logger.critical/Logger.debug etc
user_function // that called `logger.critical`

No topo do rastreio de pilha há uma linha que diz:

Error

Então, o rastreio de pilha completo pode ser imaginado desse jeito:

Error
    at get_caller_info line:number
    at Logger.#log line:number
    at Logger.critical line:number
    at user_function line:number // that called `logger.critical`

Certo, nos importamos apenas com a 5º linha.

const meta_data = caller_frame.split("at ").pop();

Nessa linha, estamos recuperando a parte da string que sucede a palavra "at" seguida por um espaço, já que não precisamos incluir isso em nosso output. Finalmente, na última linha, vamos retornar os metadados necessários para exibir nos logs.

Usando a função get_caller_info

Atualize o código na classe Logger para usar a informação fornecida pela função get_caller_info.

// file: lib/logger.js

class Logger {
    ...    
    async #log(message, log_level) {
        if (log_level < this.#config.level || !this.#log_file_handle.fd) {
            return;
        }

        const date_iso = new Date().toISOString();
        const log_level_string = LogLevel.to_string(log_level)

        // adiciona informações extras às mensagens de log.
        const log_message = `[${date_iso}] [${log_level_string}]: ${get_caller_info()} ${message}\n`;
        await this.#log_file_handle.write(log_message);
    }
    ...
}

Agora, vamos testar se tudo funciona como esperamos?

No arquivo test.js, vamos escrever alguns logs.

// file: test.js

const {Logger} = require('./index')

async function initialize() { ... }

async function main() {
    let logger = await initialize()
    logger.critical('From the main() function')
    nested_func(logger)
}

function nested_func(logger) {
    logger.critical('From the nested_func() function')
    super_nested(logger)
}

function super_nested(logger) {
    logger.critical('From the super_nested() function')
}

main()

O arquivo de log mostra o seguinte -

[2023-08-19T19:11:51.888Z] [CRITICAL]: main (/Users/ihtmeet/Code/logtard/test.js:11:12) From the main() function
[2023-08-19T19:11:51.888Z] [CRITICAL]: nested_func (/Users/ishtmeet/Code/logtard/test.js:16:12) From the nested_func() function
[2023-08-19T19:11:51.888Z] [CRITICAL]: super_nested (/Users/ishtmeet/Code/logtard/test.js:21:12) From the super_nested() function

Tudo isso parece funcionar muito bem. Agora temos logs úteis. Porém, antes de começarmos a utilizar essa biblioteca de logging em nossos projetos pessoais, há muitas coisas que precisam ser cuidadas. Isso inclui quebras de logging, gerenciar os sinais SIGINT e SIGTERM, assim como utilizar o file_handle apropriadamente.

Vamos cuidar disso no próximo capítulo.

O código de todo o capítulo pode ser encontrado no diretório code/chapter_04.3