🦑

Laravelが発行するSQLにログを追加したい

zinkosuke

2024/12/15に公開

Laravel

PHP

tech

Social Databank Advent Calendar 2024 の15日目です。

こんにちは、zinです🦑

弊社サービスの Liny では、調査用にAurora (MySQL)の監査ログやスロークエリログを取得しています。

Linyではおよそ100のECS Serviceが存在しており、500以上のコンテナが稼働しています。
メインで稼働しているAuroraはほぼ全てのコンテナから接続されており、「監査ログ取ったは良いけど、このクエリ誰が叩いたの？」状態でした。

解決策として、SQLにコンテナの情報をコメントとして付与することにしました。

サンプルプロジェクトを作成

クエリをログに出すまでのお試し環境を作成します。準備の手間を最小限にするため、MySQLではなくSQLiteを利用しています。
以下Docker Desktop for Mac (4.36.0) で実行しています。

適当なディレクトリで以下のようなDockerfileを作成します。

FROM php:8.4.1

RUN set -eux \
 && apt-get update -yqq \
 && apt-get install -y --no-install-recommends \
    git \
 && :

COPY --from=composer /usr/bin/composer /usr/bin/composer

Dockerfileがあるディレクトリでイメージをビルドし、コンテナ起動 → Laravelプロジェクトの作成までを行います。
執筆時点ではlaravel/framework 11.35.0がインストールされました。

# ビルド
docker build -t php-local:latest .
# コンテナ起動
docker run -it --rm -v `pwd`:/work -w /work -p 8000:8000 php-local:latest bash

# (コンテナ内) Laravelプロジェクトを作成, 移動
composer create-project laravel/laravel example 
cd example

テスト用サーバーを立ち上げ、 http://localhost:8000/ にアクセスしてwelcomeページが表示できたら準備完了です。

# (コンテナ内) テストサーバー起動
php artisan serve --host 0.0.0.0

Laravelが動いていることが確認できたら、Ctrl+C でサーバーを停止します。

Laravelコードリーディング

今回やりたいことは「Laravelが発行するSQLにコメントを付与する」なので、実際にSQLを組み立てている場所を探します。
tinkerでDBコネクションのクラスがどこにあるかを見てみます。

# (コンテナ内) tinker
php artisan tinker

どうやら Illuminate\Database\SQLiteConnection が怪しそうです。

> use Illuminate\Support\Facades\DB;
> $conn = DB::connection(config('database.default'))
= Illuminate\Database\SQLiteConnection {#1304}

もう少し遊んでみます。

> \App\Models\User::factory()->create()
= App\Models\User {#5273
    id: 1,
    name: "Demetris Wilderman",
    ...
  }

> $conn->select('select id from users')
= [
    {#5219
      +"id": 1,
    },
  ]

SQLiteConnectionにselectメソッドはなかったので、スーパークラスである Illuminate\Database\Connection をのぞいてみます。

Connectionクラスのselect → run → runQueryCallbackと呼び出しが続き、最後にselectメソッドで定義したコールバックが呼ばれていました。
insert, update, deleteも渡しているコールバックの実装が異なりますが、流れは同じようです。

QueryBuilder経由での呼び出しについても Illuminate\Database\Query\Builder のgetやupdateの中身を追っていくと、最終的にConnectionクラスのメソッドが呼ばれていることが確認できます。

Eloquent ModelからQueryBuilderが呼ばれるまでの仕組みについては弊社メンバーの記事があるのでこちらもぜひ。

方針を考える

ここまででクエリ実行の流れが把握できたので、どこを変えれば良いかを考えます。
Connectionから直接クエリを実行する場合とQueryBuilder経由の場合で共通して呼び出されるのはConnection::runメソッドです。
ただ、よく見ると tryAgainIfCausedByLostConnection というメソッドにコネクション起因でエラーが発生した場合1回だけリトライするという処理がしこまれていました。
よって、クエリ実行の際に必ず通るのはrunQueryCallbackメソッドだということがわかりました。
ここに手を入れていきます。

いざ実装

方針も決まったので実装していきます。
このサンプルではapp/Extension配下にファイルを置くことにします。
MySQLで実装する場合はSQLiteの部分をMySQLに置き換えればそのまま使えます。

以下の3つのファイルを新規作成します。

app/Extension/CustomDatabaseServiceProvider.php
app/Extension/CustomConnectionFactory.php
app/Extension/CustomSQLiteConnection.php

それぞれのファイルには以下の内容を貼り付けます。

app/Extension/CustomDatabaseServiceProvider.php

<?php

namespace App\Extension;

use Illuminate\Database\DatabaseManager;
use Illuminate\Database\DatabaseTransactionsManager;

class CustomDatabaseServiceProvider extends \Illuminate\Database\DatabaseServiceProvider
{
    /**
     * Register the primary database bindings.
     *
     * @return void
     */
    protected function registerConnectionServices()
    {
        // The connection factory is used to create the actual connection instances on
        // the database. We will inject the factory into the manager so that it may
        // make the connections while they are actually needed and not of before.
        $this->app->singleton('db.factory', function ($app) {
            return new CustomConnectionFactory($app); // 変更点
        });

        // The database manager is used to resolve various connections, since multiple
        // connections might be managed. It also implements the connection resolver
        // interface which may be used by other components requiring connections.
        $this->app->singleton('db', function ($app) {
            return new DatabaseManager($app, $app['db.factory']);
        });

        $this->app->bind('db.connection', function ($app) {
            return $app['db']->connection();
        });

        $this->app->bind('db.schema', function ($app) {
            return $app['db']->connection()->getSchemaBuilder();
        });

        $this->app->singleton('db.transactions', function ($app) {
            return new DatabaseTransactionsManager;
        });
    }
}

app/Extension/CustomConnectionFactory.php

<?php

namespace App\Extension;

use Illuminate\Database\Connection;
use Illuminate\Database\MariaDbConnection;
use Illuminate\Database\MySqlConnection;
use Illuminate\Database\PostgresConnection;
use Illuminate\Database\SqlServerConnection;

class CustomConnectionFactory extends \Illuminate\Database\Connectors\ConnectionFactory
{
    /**
     * Create a new connection instance.
     *
     * @param  string  $driver
     * @param  \PDO|\Closure  $connection
     * @param  string  $database
     * @param  string  $prefix
     * @param  array  $config
     * @return \Illuminate\Database\Connection
     *
     * @throws \InvalidArgumentException
     */
    protected function createConnection($driver, $connection, $database, $prefix = '', array $config = [])
    {
        if ($resolver = Connection::getResolver($driver)) {
            return $resolver($connection, $database, $prefix, $config);
        }

        return match ($driver) {
            'mysql' => new MySqlConnection($connection, $database, $prefix, $config),
            'mariadb' => new MariaDbConnection($connection, $database, $prefix, $config),
            'pgsql' => new PostgresConnection($connection, $database, $prefix, $config),
            'sqlite' => new CustomSQLiteConnection($connection, $database, $prefix, $config), // 変更点
            'sqlsrv' => new SqlServerConnection($connection, $database, $prefix, $config),
            default => throw new InvalidArgumentException("Unsupported driver [{$driver}]."),
        };
    }
}

app/Extension/CustomSQLiteConnection.php

<?php

namespace App\Extension;

use Closure;
use Exception;
use Illuminate\Database\QueryException;
use Illuminate\Database\UniqueConstraintViolationException;
use Illuminate\Support\Str;

class CustomSQLiteConnection extends \Illuminate\Database\SQLiteConnection
{
    /**
     * Run a SQL statement.
     *
     * @param  string  $query
     * @param  array  $bindings
     * @param  \Closure  $callback
     * @return mixed
     *
     * @throws \Illuminate\Database\QueryException
     */
    protected function runQueryCallback($query, $bindings, Closure $callback)
    {
        // To execute the statement, we'll simply call the callback, which will actually
        // run the SQL against the PDO connection. Then we can calculate the time it
        // took to execute and log the query SQL, bindings and time in our memory.
        try {
            // 変更点
            $query = Str::finish(trim($query), ";");
            if (Str::endsWith($query, ";")) {
                $query = rtrim($query, ";");
            }
            $query .= " /* ここに値を入れる */;";

            return $callback($query, $bindings);
        }

        // If an exception occurs when attempting to run a query, we'll format the error
        // message to include the bindings with SQL, which will make this exception a
        // lot more helpful to the developer instead of just the database's errors.
        catch (Exception $e) {
            if ($this->isUniqueConstraintError($e)) {
                throw new UniqueConstraintViolationException(
                    $this->getName(), $query, $this->prepareBindings($bindings), $e
                );
            }

            throw new QueryException(
                $this->getName(), $query, $this->prepareBindings($bindings), $e
            );
        }
    }
}

最後にServiceProviderを置き換えます。
Laravel 11からServiceProviderの登録方法が変わったようで、独自に追加するものであればbootstrap/providers.phpに追加すれば良さそうです。
今回はデフォルトで登録されているServiceProviderの置き換えになるので、config/app.phpにprovidersを追加します。

config/app.php

<?php

use Illuminate\Support\ServiceProvider;

return [
    // 既存のものは触らなくて良い

    /*
    |--------------------------------------------------------------------------
    | Autoloaded Service Providers
    |--------------------------------------------------------------------------
    |
    | The service providers listed here will be automatically loaded on any
    | requests to your application. You may add your own services to the
    | arrays below to provide additional features to this application.
    |
    */

    'providers' => ServiceProvider::defaultProviders()->replace([
        \Illuminate\Database\DatabaseServiceProvider::class => \App\Extension\CustomDatabaseServiceProvider::class,
    ])->toArray(),
];

動作確認

再びtinkerでクエリを実行して /* ここに値を入れる */ が追加されているかを確認します。
SQLiteには監査ログのような機能がないので、構文エラーを起こしてExceptionの内容から確認することにします。

# (コンテナ内) tinker
php artisan tinker

> use Illuminate\Support\Facades\DB;
> $conn = DB::connection(config('database.default'))
= App\Extension\CustomSQLiteConnection {#1304}

> $conn->select('select id from sonzai_shinai_table')

   Illuminate\Database\QueryException  SQLSTATE[HY000]: General error: 1 no such table: sonzaishinai_table (Connection: sqlite, SQL: select id from sonzai_shinai_table /* ここに値を入れる */;).

SQLにコメントが追加されているのが確認できました。
Linyでは環境変数からECS Service名やプロセスごとに割り当てられるIDなどをコメントに埋め込んでいます。

おわりに

デフォルトのServiceProviderを置き換えるのでややリスクが高い実装にはなりますが、スロークエリの特定などで役立っています。
今回はSQLにコメントを追加しましたが、アプリケーションログにSQLを出すのであればDB::listenを使ってもっと簡単にできるようでした。目的に合わせて使い分けられると良さそうです。

ソーシャルデータバンクテックブログ

ソーシャルデータバンク株式会社の開発チームです。インフラ、品質、UI/UX、DevOpsなど様々な活動に取り組んでいます。