Investigating an incident: how to log effectively (PHP)

Why do we need loggers?

It's common for humans to make mistakes. That's so not only in the relation of developers but also users. And if while developing we control the process totally and can see the wrong behavior through with simple debugging, the same case on the productions environment wouldn't be so easy to investigate. In such cases the thing to help us are journals. But to gain a maximum value of its usage we should do it properly.

Logging – the process of maintaining such journals, and it helps to detect hidden errors, understand user problems and simply sort out what really happened. In the simplest implementation logs are written to the text files and contain an exact time and description of the event. There is a bunch of methods to do that, and what is good for us – the best practices were defined long ago.

In this article, we'll sort out how to organize logging in a PHP app, how to use it efficiently, and what libraries might be useful.

PSR-3 Standard. Log levels

PSR is a collection of general recommendations for PHP developers. It contains tips for code style, some interfaces, and other recommendations. One of its documents (PSR-3) is dedicated to a logger implementation.

I suggest that you start getting acquainted with these recommendations with the logging levels that it offers.

<?php

namespace Psr\Log;

class LogLevel
{
    const EMERGENCY = 'emergency';
    const ALERT     = 'alert';
    const CRITICAL  = 'critical';
    const ERROR     = 'error';
    const WARNING   = 'warning';
    const NOTICE    = 'notice';
    const INFO      = 'info';
    const DEBUG     = 'debug';
}

PSR-3 defines 8 different message levels. Proper usage of them will simplify searching for errors and will boost up an accident reaction speed. Let's go deeper and figure out when to use them.

DEBUG – debugging information that reveals the details of the event in detail;
INFO – any interesting events. For instance: user has signed in;
NOTICE – important events within the expected behavior;
WARNING – exceptional cases which are still not errors. For example usage of a deprecated method or wrong API request;
ERROR – errors to be monitored, but which don't require an urgent fixing;
CRITICAL – critical state or an event. For instance: unavailability of a component or an unhandled exception;
ALERT – error and an event to be solved in the shortest time. For example, the database is unavailable;
EMERGENCY – whole app/system is completely out of order.

Use of these levels means just adding it as some kind of prefix to your log message. For instance:

[2021-01-01 12:10:35] website.INFO: User has changed his password

Such levels as ALERT and EMERGENCY are commonly handled with an additional notification (SMS, Email, and so on). INFO allows you to reproduce the whole user's action sequence, while DEBUG will simplify exact values and function's results fetching.

PSR-3. Logger Interface

In addition to the class with levels, PSR-3 offers us an interface for implementing our own loggers - LoggerInterface. Its implementation is very useful because most existing libraries support it, and if you decide to replace your logger with another one, just connect a new class instead.

LoggerInterface requires the implementation of logging methods, in accordance with the previously reviewed levels. Let's create our own logger class that will correspond to this interface and writes messages to a text file.

But first, let's download the PSR-3 code with Composer.

composer req psr/log

The package we downloaded contains several classes, traits, and interfaces, among which the LogLevel we previously reviewed, and the LoggerInterface that is currently of our interest. Let's create a new class that implements that interface. Important: make sure that you have the autoloader class included (vendor/autoload.php).

<?php
// index.php

// Composer's autoloader
require_once 'vendor/autoload.php';
// Our new Logger class
require_once 'src/FileLogger.php';

<?php
// src/FileLogger.php

// If `use` was not added automatically, 
// be sure to add it yourself
use Psr\Log\LoggerInterface;

// Implement the downloaded interface
class FileLogger implements LoggerInterface
{
    // ...
}

We created the class, but in order for it to meet the requirements of the standard, you need to write all the methods described in the interface. The most important of them is log. The main logic of logging into the file will be written in it.

class FileLogger implements LoggerInterface
{
    // ...
    public function log($level, $message, array $context = []): void
    {
        // Current date in 1970-12-01 23:59:59 format
        $dateFormatted = (new \DateTime())->format('Y-m-d H:i:s');

        // Build the message with the current date, log level, 
        // and the string from the arguments
        $message = sprintf(
            '[%s] %s: %s%s',
            $dateFormatted,
            $level,
            $message,
            PHP_EOL // Line break
        );

        // Writing to the file `devto.log`
        file_put_contents('devto.log', $message, FILE_APPEND);
        // FILE_APPEND flag prevents flushing the file content on each call 
        // and simply adds a new string to it
    }
    // ...
}

To fully satisfy the LoggerInterface, we need to write an implementation for the emergency, alert, critical, error, warning, notice, info and debug methods, which correspond to the levels we have previously reviewed. Their implementation boils down to a very simple principle – we call the log method, passing the necessary level to it.

class FileLogger implements LoggerInterface
{
    // ...
    public function emergency($message, array $context = []): void
    {
        // Use the level from LogLevel class
        $this->log(LogLevel::EMERGENCY, $message, $context);
    }

    public function alert($message, array $context = []): void
    {
        $this->log(LogLevel::ALERT, $message, $context);
    }
    // and so on...
    // ...
}

Use of logger

Now that our class implements the interface proposed by the PSR-3 standard, we can easily use it anywhere. For example, in the file index.php:

<?php
// index.php

// Composer's autoloader
require_once 'vendor/autoload.php';
// Our new Logger class
require_once 'src/FileLogger.php';

$logger = new FileLogger();
$logger->debug('Message from index.php');

Or in any other class:

<?php

use Psr\Log\LoggerInterface;

class ExampleService
{
    /** @var LoggerInterface */
    private $logger;

    public function __construct(LoggerInterface $logger)
    {
        $this->logger = $logger;
    }

    public function doSomeAction(): void
    {
        // do some work
        $this->logger->debug('Message from ExampleService');
    }
}

Please note that we do not specify the final implementation (FileLogger) as the type of the constructor argument, but the interface of the PSR-3 standard. This is very convenient because it allows us to very easily replace the used logger with any other one that supports this interface.

Context

You may have noticed that all methods of the LoggerInterface contain the $context argument. Why is it needed?

The context is intended for transmitting auxiliary and, often, dynamic information. For example, if you are making a debug entry (debug level), you can pass the value of a variable to the context.

In order to apply this argument, we need to support it in the log method. Let's refine it, given that $context is an array.

class FileLogger implements LoggerInterface
{
    // ...
    public function log($level, $message, array $context = []): void
    {
        $dateFormatted = (new \DateTime())->format('Y-m-d H:i:s');

        // Let's convert $context array into json
        $contextString = json_encode($context);
        $message = sprintf(
            '[%s] %s: %s %s%s',
            $dateFormatted,
            $level,
            $message,
            $contextString, // Add context string
            PHP_EOL
        );

        file_put_contents('devto.log', $message, FILE_APPEND);
    }
    // ...
}

Now, at any place of the logger call, we can pass an array of additional information with the second argument.

<?php
// index.php
//...

$userName = 'Elijah';
$userEmail = 'elijah@dev.to';

$logger = new FileLogger();
$logger->debug('Message from index.php', [
    'user_name' => $userName,
    'user_email' => $userEmail,
]);

As a result, we will get a record of the following form:

[2021-09-02 13:00:24] debug: Message from index.php {"user_name":"Elijah","user_email":"elijah@dev.to"}

Regarding the context, there is one very simple rule: any dynamic information should be transmitted in it, but not in the message. That is, if you form a message into a log using sprintf or concatenation of string variables, most likely this information can be put into the context. Following this rule simplifies the search in the log because it eliminates the need to predict (or calculate) the values of variables.

The Monolog library

Despite the simplicity of the logging principle, there is a very wide scope for modifications in this area. We could support other record formats, implement SMS sending, or simply allow you to change the name of the final log file.

Fortunately, all this has been implemented in most libraries for a long time, and one of the most common is monolog.

Among the most significant advantages of this package are:

Full support for PSR-3;
Support for different principles of log handling, depending on the level;
Support for channel names (logger names);
Very wide support of frameworks.

To start using this beautiful tool, we will install it using Composer.

composer req monolog/monolog

The Monolog usage

The main idea of the monolog library is handlers. They allow you to set specific behavior for logging events. For example, to write a message to a text file we'll use StreamHandler. Let's replace the use of our class with the loaded library.

<?php

// index.php

use Monolog\Logger;
use Monolog\Handler\StreamHandler;

// Composer's autoloader
require_once 'vendor/autoload.php';

// We pass a channel name as the argument for Logger
$logger = new Logger('devto-demo');
// Connect the handler. Argument for StreamHandler is a path to a file
$logger->pushHandler(new StreamHandler('devto.log'));

// Then we leave everything as it was
$userName = 'Elijah';
$userEmail = 'elijah@dev.to';
$logger->debug('Message from index.php', [
    'user_name' => $userName,
    'user_email' => $userEmail,
]);

If we run this code, the following entry will appear in the devto.log file:

[2021-09-02T13:16:14.122686+00:00] devto-demo.DEBUG: Message from index.php {"user_name":"Elijah","user_email":"elijah@dev.to"} []

This is very similar to what we had earlier, except for adding the channel name (devto-demo).

An important feature of Monolog handlers is that they can be set the level at which they work. For example, we can write all the errors in a separate file.

<?php

// index.php

use Monolog\Handler\StreamHandler;
use Monolog\Logger;
use Psr\Log\LogLevel;

// ...
$logger = new Logger('devto-demo');
$logger->pushHandler(new StreamHandler('devto.log'));
$logger->pushHandler(new StreamHandler('errors.log', LogLevel::ERROR));

// ...
$logger->emergency('It is not even an error. It is EMERGENCY!!!');

The handler connected to the ERROR level will take overall records of the ERROR level and higher. Therefore, the call to the emergency method falls into both files: devto.log and errors.log

This simple division of records into levels greatly simplifies our reaction to errors. After all, we no longer need to look for them among all the other entries in the log. This is a very simple and useful function.

Log records of the request

In the process of developing our project, the logs are read very simply. They are consistent and clear. But when several people use the product, the logs can get mixed up and just confuse to a greater extent than they help. There is a very simple trick to solve this problem. Instead of the channel name, use a unique session ID. You can get it using the built-in function session_id(). (The session must be started using session_start())

Let's look at an example of the implementation of such a technique:

<?php
// index.php

// Start the session
session_start();

// ...

// Pass the session id as a channel name
$logger = new Logger(session_id());
// ...

What does such a simple refactor give us? A very important feature is to group all records by user requests.

// First request records
[2021-09-02T13:35:54.155043+00:00] b30m8k1fvmf638au7ph0edb3o5.DEBUG: Message from index.php {"user_name":"Elijah","user_email":"elijah@dev.to"} []
[2021-09-02T13:35:54.156800+00:00] b30m8k1fvmf638au7ph0edb3o5.EMERGENCY: It is not even an error. It is EMERGENCY!!! [] []
// Another request records. They have different ids
[2021-09-02T13:36:03.528474+00:00] u7fi04mn99h0timg148rles1um.DEBUG: Message from index.php {"user_name":"Elijah","user_email":"elijah@dev.to"} []
[2021-09-02T13:36:03.529421+00:00] u7fi04mn99h0timg148rles1um.EMERGENCY: It is not even an error. It is EMERGENCY!!! [] []

What's next?

The Monolog supports a lot of very useful ready-made handlers that are worth paying attention to:

TelegramBotHandler – Sends logs via Telegram Bot. Very useful for high levels of logging;
SlackHandler – Very similar to the previous one, but sends records to Slack;
SwiftMailerHandler – Allows to send logs with email;
ChromePHPHandler – Gives access to logs directly from the Chrome browser in Live mode!

Conclusion

Logging is a simple and important tool. It will help you fix errors at an early stage, be sure that nothing is broken in the new version of the code, investigate the cases of your users and have general visibility on the project.

The main thing is to remember the simple rules:

Following PSR-3 will make it easier for you to replace logger classes in your code and will allow you to use external libraries;
Different logging levels will help you focus on what is important;
Separation of dynamic information into context will simplify the search through logs;
The Monolog library implements almost all possible programmer's requirements. Be sure to take the time to study it;
Using the session ID, you can separate log entries for each request;
It is better to write a lot of extra logs than not to add one important one.

Blog