Log adequado em PHP com PSR-3

Para quem é este artigo?

Esta postagem é para pessoas que realizam tarefas diárias de codificação e para líderes de equipe que desejam direcionar seus colegas para melhores práticas de registro.

Observe que este artigo surge da minha necessidade regular de apresentar esses pontos exatos para pessoas diferentes, várias vezes por ano, em várias equipes, em várias empresas.

Além disso, não falaremos sobre como configurar um registrador PSR-3, mas sim como usar um.

Lidando com erros corretamente

O tratamento de erros/exceções é o principal caso de uso para registro.

Ao registrar exceções, passe o Throwable instância para o 'exception' chave de contexto.

try {
    // logic here
} catch (SomeException $failed) {
    $this->logger->error('Something went wrong', (
        'exception' => $failed,
    ));
}

Evite sobrecarregar a chamada do criador de logs com dados provenientes da exceção: esse não é o trabalho do site de chamada do criador de logs e você está apenas repetindo o trabalho.

Muitas vezes vejo código desnecessário como:

try {
    // logic here
} catch (SomeException $failed) {
    $this->logger->error('Something went wrong', (
        // first mistake: we forgot 'exception'
        'previous' => $failed->getPrevious(), // let the logger do this!
        'line' => $failed->getLine(), // already part of the stack trace
        'error' => $failed->getMessage(), // also always rendered
        'error_type' => $failed::class, // done by the logger, usually
    ));
}

O próprio logger deve estar configurado (e geralmente já é configurado) para renderizar:

• a exceção ::class

• a mensagem e o código de exceção (os códigos não são mais relevantes neste século)

• o rastreamento de pilha

• exceções anteriores

• campos de exceção adicionais

Sua responsabilidade é, em vez disso, passar contexto Informação que o criador de logs não pode inferir por conta própria.

E se meu código falhar normalmente e não levanta uma exceção?

if (is_wrong($something)) {
    $this->logger->warn('Something went wrong', ('something' => $something));
}

Para falhas específicas de negócios que merecem um tipo, podemos transformá-las em um Throwable de qualquer forma:

if (is_wrong($something)) {
    $this->logger->warn('Something went wrong', (
        'something' => $something,
        'exception' => new SomethingWentWrong($something), // Throwable
    ));
}

Ter tipos de exceção claros, mesmo se usados ​​apenas com o criador de logs, permitirá detectar facilmente vários locais de código afetados pelo mesmo tipo de falha posteriormente.

Cuidado: o levantamento de exceções e o registro em log vêm com sobrecarga substancial de CPU, memória e E/S, portanto, você deve sempre decidir com cuidado quando o registro em log e as exceções podem ser gerados em um loop restrito.

Lembre-se também que um Throwable sempre coleta todo o rastreamento de pilha a partir do qual foi gerado, o que pode afetar a coleta de lixo, se o criador de logs mantiver mensagens na memória.

Os registradores são perfeitamente capazes de determinar o rastreamento de pilha de uma mensagem de log gerada: o 'exception'
chave não é necessária para que esse recurso funcione, portanto, criar uma nova Throwable é sua decisão.

“Alguns registros” são melhores que “sem registros”

Pessoalmente, não sou fã de sobrecarregar o código com instruções de log e depuração, mas é inegável que o registro ajudará você a manter uma compreensão geral de como seu software está se comportando na produção, tanto quando saudável quanto não saudável.

Um sistema que produz sem saída pode estar funcionando perfeitamente ou estar completamente quebrado: ter uma ideia se “ainda está funcionando” é uma boa ideia.

Não tenho certeza se está tudo bem ou o monitoramento está quebrado.

Eu recomendo ter $logger->info('Heartbeat'); ou chamadas semelhantes em código executado em operações de longa duração, loops de pesquisa ou que ficam ociosos, aguardando entrada:

$eventLoop->whenever(function ($someEvent) {
    // main application logic
});

$eventLoop->periodically(function () {
    $this->logger->info('still here, waiting for you');
}, Time::seconds()->multiply(120));

$eventLoop->run();

Você pode configurar o registrador ou o site de chamadas para registrar apenas uma porcentagem das chamadas, caso contrário o sistema ficaria muito tagarela.

O registro periódico não substitui uma sondagem externa de verificação de integridade .

Observe que você também pode querer usar métricas (mais sobre isso abaixo).

Injetando registradores

Por favor usar injeção de dependência ao solicitar um registrador:

final readonly class MyService implements SomeService
{
    public function __construct(private LoggerInterface $logger) {}

    function someLogic() {
        $this->logger->debug('Look ma, I got the logger via DI!');
    }
}

Além de evitar as armadilhas da localização do serviço e do estado global, você obtém:

• uma declaração clara de que sua unidade de código emitirá mensagens de log

• a possibilidade de escolher um logger específico para cada serviço

• a capacidade de usar espiões/simulações de testes não mágicos para verificar comportamentos de registro

Veja como personalizar o criador de logs em uma definição de serviço:

$serviceDefinitions->add(
    SomeService::class,
    function (MainLogger $rootLogger) { 
        return new MyService(
            $rootLogger
                ->forWiredService(SomeService::class)
                ->withEnvironment($someEnvironment)
        );
    }
);

Veja como alguém poderia trabalhar com mensagens de log em um teste:

#(Test)
function my_service_does_a_bunch_of_things_in_a_very_specific_order(): void
{
    $testSpyLogger = new RecordingLogger();

    $systemUnderTest = new MyService($testSpyLogger);

    $systemUnderTest->doSomeWork();

    Assert::equals(
        (
            'Extracted data',
            'processed row A',
            'processed row B',
            'failed to process row C',
            'finished',
        ),
        $testSpyLogger->messages
    );
}

Usando o registrador para medições?

Muitas vezes vejo equipes usando registradores para registrar informações métricas e, em seguida, grepexecutar ping no resultado, para produzir gráficos ou dados analíticos adicionais:

final readonly class LoggedCart implements CartService {
    public function __construct(
        // ...
        private LoggerInterface $logger,
    ) {}

    public function cartCheckout(
        // ...
    ): void {
        // ...

        $this->logger->info(
            'cart.checkout',
            ('total_amount' => $cart->totalAmount())
        );
    }
}

Embora você certamente possa fazer isso, o logger é a abstração errada para métricas.

A ferramenta correta para métricas são as métricas OTEL (embora qualquer ferramenta “semelhante a métricas” também funcione):

final readonly class LoggedCart implements CartService {
    public function __construct(
        // ...
        MeterProvider $metrics,
    ) {
        $this->checkoutAmounts = $metrics->createHistogram('cart.checkout.total_amount');
    }

    public function cartCheckout(
        // ...
    ): void {
        // ...

        $this->checkoutAmounts->record($cart->totalAmount());
    }
}

Veja também o MeterProviderInterface.

Com essa configuração, suas métricas podem ser coletadas com mais eficiência (em lotes) e podem ser enviadas para back-ends dedicados, como bancos de dados de série temporal, prontos para serem visualizados.

Observe que você ainda está livre para conectar o leitor de métricas para que ele encaminhe as métricas registradas para o seu registrador!

Durações de registro

Freqüentemente, você verá desenvolvedores registrando o tempo decorrido de uma operação:

final readonly class CreditCardCheckout implements Checkout {
    public function __construct(
        // ...
        private LoggerInterface $logger,
    ) {}

    public function cartCheckout(
        // ...
    ): void {
        $start = $this->clock->now();
        $this->logger->debug('checkout.start', ('time' => $start))
        // ...

        $end = $this->clock->now();
        $this->logger->log(
            'checkout.end',
            (
                'time'     => $end,
                'duration' => $end->diff($start)
            )
        );
    }
}

Da mesma forma que as métricas, um logger não é a abstração correta: em vez disso, consulte OTEL Tracing

Os rastreamentos permitem uma implementação mais limpa:

final readonly class CreditCardCheckout implements Checkout {
    public function __construct(
        // ...
        private Tracer $tracer,
    ) {}

    public function cartCheckout(
        // ...
    ): void {
        $span = $this->tracer->spanBuilder('checkout')
            ->startSpan();

        // ... 

        $span->end();
    }
}

A API pode ser melhorada ainda mais com o seu próprio Tracer adições, e você ainda pode enviar o início/fim do intervalo para o seu registrador.

Ao usar a abstração correta, um software coletor de rastreamento dedicado (como Jaeger, Zipkin, AWS X-Ray, etc.) pode fornecer informações completas sobre como as operações são aninhadas, executadas simultaneamente, etc.:

Interpolação de mensagens

Por favor, não faça isso:

$this->logger->info('user ' . $user->username() . ' logged in');

PSR-3 especifica um {bracket_based} convenção de interpolação de mensagens, na qual você pode confiar:

$this->logger->info(
    'user {username} logged in',
    ('username' => $user->username())
);

Com o acima, você ganha:

• um campo “nome de usuário” estruturado e pesquisável em seus registros

• clareza sobre quais bits da mensagem são dinâmicos, especialmente quando valores interpolados contêm espaços

Lembre-se de que esse comportamento precisa estar habilitado.

Níveis de registro

O nível de log afeta principalmente:

• se a mensagem de log será emitida

• quem será notificado

É importante não aumentar o nível do log desnecessariamente, ou você pode se deparar com um disco cheio, um sistema de monitoramento limitado, uma caixa de entrada de e-mail cheia ou um colega de trabalho de plantão irritado.

Os registros devem chamar nossa atenção apenas quando relevantes: a atenção é uma moeda valiosa

Ao revisar o novo código, sempre pergunte-se se você pode “empurrar o nível do log para baixo”.

Para loops apertados, debug poderia ser suficiente. Você também não deseja ver essas mensagens em produção: elas devem estar desativadas por padrão.

As operações bem sucedidas deverão provavelmente receber uma info nível: você também deseja saber se um sistema está funcionando corretamente.

Para manchas aceitáveis ​​em seus dados, um notice poderia funcionar.

O processamento de dados que falhou, mas foi recuperado com um fallback, provavelmente deverá receber uma warning.

Qualquer coisa de exception up deve ser discutido dentro de sua equipe e domínio de negócios, quando apresentado.

Evite realizar E/S durante o registro

O registro é um assunto delicado: evite torná-lo mais delicado, pois é seu último recurso na tentativa de entender um sistema com falha.

O código a seguir é problemático:

$this->logger->error(
    'user {username} failed to log in',
    (
        'exception' => $exception,
        'username'  => $this->users->get($userId)->username()
    )
);

Neste estágio, você não sabe se o sistema está em estado irrecuperável e toda essa expressão pode falhar.

Além disso, sua operação de registro está potencialmente desacelerando o sistema: talvez o registro $userId
foi suficiente?

Como regra geral, o site de chamada do criador de logs não deve avaliar expressões que possam @throwou que interagem com o estado global (um @phpstan-pure ou @psalm-pure declaração pode ajudar).

Conclusão

Esperamos que este artigo contenha coisas que você pode apontar ao discutir o uso do logger com seus colegas: eu com certeza precisava deste compêndio de padrões para meu futuro ☺️