Customizing Log Output in Laravel

Environment

• Laravel 6

Creating the Logging Classes

First, let's create Formatter classes in app/Logging/ that define the content of the action logs. The Action and Query logs differ in their output format. Also, depending on the environment, calling Auth::id() to get the user ID can trigger a DB access, so in QueryLogFormatter we control this using the static variable $disableUserId. If anyone knows a better way to handle this, I'd love to hear about it.

// app/Logging/ActionLogFormatter.php
<?php 
namespace App\Logging;

use Illuminate\Support\Facades\Auth;
use Monolog\Formatter\LineFormatter;
use Monolog\Logger;
use Monolog\Processor\IntrospectionProcessor;
use Monolog\Processor\UidProcessor;

class ActionLogFormatter
{
    private $dateFormat = 'Y-m-d H:i:s.v';
    public function __invoke($logger)
    {
        // Specify the log format and date format
        $format = '[%datetime%] action %channel%.%level_name% %extra.uid% %extra.userid%" %message% %context% ' . PHP_EOL;
        $lineFormatter = new LineFormatter($format, $this->dateFormat, true, true);

        // Processing to attach an ID for tying the output log to the request
        $uidProcessor = app()->make(UidProcessor::class);

        // Specify namespaces to exclude from the log output
        $introProcessor = new IntrospectionProcessor(Logger::DEBUG, [
            'Monolog\\',
            'Illuminate\\',
            'App\\Providers\\',
            'App\\Logging\\',
        ]);

        // Set up the formatter and content
        foreach ($logger->getHandlers() as $handler) {
            $handler->setFormatter($lineFormatter);
            $handler->pushProcessor($introProcessor);
            $handler->pushProcessor($uidProcessor);
            $handler->pushProcessor(function (array $record) {
                $record['extra']['userid'] = Auth::id() ?? '';
                return $record;
            });
        }
    }
}

// app/Logging/QueryLogFormatter.php
<?php
namespace App\Logging;
use Illuminate\Support\Facades\Auth;
use Monolog\Formatter\LineFormatter;
use Monolog\Logger;
use Monolog\Processor\IntrospectionProcessor;
use Monolog\Processor\UidProcessor;

class QueryLogFormatter
{
    /**
     * NOTE
     *  Flag used to avoid an infinite loop in query log output, since calling
     *  Auth::id() to get the user ID triggers a DB access
     * @var bool
     */
    private static bool $disableUserId = false;

    private $dateFormat = 'Y-m-d H:i:s.v';
    public function __invoke($logger)
    {
        $format = '[%datetime%] query %channel%.%level_name% %extra.uid% %extra.userid% query %extra.file%(%extra.line%) %message% %context% ' . PHP_EOL;
        if (self::$disableUserId) {
            $format = '[%datetime%] query %channel%.%level_name% %extra.uid% %extra.file%(%extra.line%) %message% %context% ' . PHP_EOL;
        }

        // Specify the log format and date format
        $lineFormatter = new LineFormatter($format, $this->dateFormat, true, true);

        $uidProcessor = app()->make(UidProcessor::class);
        $introProcessor = new IntrospectionProcessor(Logger::DEBUG, [
            'Monolog\\',
            'Illuminate\\',
            'App\\Providers\\',
            'App\\Logging\\',
        ]);

        foreach ($logger->getHandlers() as $handler) {
            $handler->setFormatter($lineFormatter);
            $handler->pushProcessor($introProcessor);
            $handler->pushProcessor($uidProcessor);

            $handler->pushProcessor(function (array $record) {
                if (self::$disableUserId) {
                    return $record;
                }
                try {
                    self::$disableUserId = true;
                    $record['extra']['userid'] = Auth::id() ?? '';
                } finally {
                    self::$disableUserId = false;
                }
                return $record;
            });
        }
    }
}

Configuring logging.php

Next, in Laravel, logging settings are described in config/logging.php. This file is created at install time, so we'll edit it. We add channels for outputting the action and query logs we created. By specifying the Formatter class we just created in tap, we can switch the Formatter used for the specified channel when logging.

// config/logging.php
<?php
return [
    'channels' => [

        ...

        'action' => [
            'driver' => 'daily',
            'path' => storage_path('logs/laravel.log'),
            'level' => 'info',
            'days' => 7,
            'permission' => 0777,
            'tap' => [App\Logging\ActionLogFormatter::class],
        ],

        'query' => [
            'driver' => 'daily',
            'path' => storage_path('logs/laravel.log'),
            'level' => 'info',
            'days' => 7,
            'permission' => 0777,
            'tap' => [App\Logging\QueryLogFormatter::class],
        ],
    ],
];

Outputting Logs

Now let's implement the code that actually outputs the logs. Naturally, the action log and the query log fire at different times, so the code goes in different places.

Action Log

Since we want the action log to be output when Laravel receives a request, we create a Middleware to output the log there. This class is also where we mask any content — such as passwords or personal information — that shouldn't be left in the log as plain text.

// Http/Middleware/ActionLogMiddleware.php
<?php
namespace App\Http\Middleware;
use Closure;
use Illuminate\Support\Facades\Log;
class ActionLogMiddleware
{
    public function handle($request, Closure $next)
    {
        $logContext = [
            'url' => $request->path(),
            'request' => $this->maskRequest($request->all()),
        ];
        Log::channel('action')->info($request->method(), $logContext);
        return $next($request);
    }

    public function maskRequest($params)
    {
    　　　　　　　　# Mask any values sent under the keys "password" or "password_confirmation".
        # Add more entries here if you need to mask other fields as well
        array_walk_recursive($params, function (&$val, $key) {
            if (($key === 'password')||($key === 'password_confirmation')) {
                $val = '********';
            }
        });
        return $params;
    }
}

Query Log

The query log outputs a log entry whenever SQL is executed. To achieve this in Laravel, we create a ServiceProvider dedicated to query log output and register it with the application.

// Providers/QueryLogServiceProvider.php
<?php
namespace App\Providers;
use Illuminate\Database\Events\TransactionBeginning;
use Illuminate\Database\Events\TransactionCommitted;
use Illuminate\Database\Events\TransactionRolledBack;
use Illuminate\Support\Facades\DB;
use Illuminate\Support\Facades\Event;
use Illuminate\Support\Facades\Log;
use Illuminate\Support\ServiceProvider;

class QueryLogServiceProvider extends ServiceProvider
{
    public function register(): void
    {
        DB::listen(function ($query) {
            $sql = $query->sql;
            for ($i = 0; $i < count($query->bindings); $i++) {
                if (! is_object($query->bindings[$i])) {
                    $sql = preg_replace("/\?/", $query->bindings[$i], $sql, 1);
                } else {
                    $sql = preg_replace("/\?/", date_format($query->bindings[$i], 'Y-m-d'), $sql, 1);
                }
            }
            $this->writeLog($sql);
        });

        Event::listen(TransactionBeginning::class, function (TransactionBeginning $event): void {
            $this->writeLog('begin transaction');
        });

        Event::listen(TransactionCommitted::class, function (TransactionCommitted $event): void {
            $this->writeLog('commit transaction');
        });

        Event::listen(TransactionRolledBack::class, function (TransactionRolledBack $event): void {
            $this->writeLog('rollback transaction');
        });
    }

    private function writeLog($msg)
    {
        Log::channel('query')->info($msg);
    }
}

// config/app.php
<?php
return [

    ...

    'providers' => [

        ...

        \App\Providers\QueryLogServiceProvider::class

        ...
    ]
    ...

]

Articles I referenced

Outputting the executed SQL query log in Laravel Attaching a per-request ID to Laravel logs