[Laravel] SQLログをいい感じに整形して出力させる

# 概要

webアプリケーションを開発する際、アプリケーションが実行したSQLクエリの確認は欠かせません。ロギング周りの調整は開発の初期の段階でアプリケーションに仕込むことがほとんどだと思います。
今回は、LaravelでSQLログをいい感じに整形して出力する方法を紹介します。

# サービスプロバイダを作る

```shell
php artisan make:provider DataBaseQueryLoggerServiceProvider
```

### app.phpに登録する

```config/app.php
    'providers' = [
        //
        App\Providers\DataBaseQueryLoggerServiceProvider::class,
    ],
```

できたファイルをこんな感じにする。


```app/Providers/DataBaseQueryLoggerServiceProvide.php
<?php

namespace App\Providers;

use Illuminate\Support\ServiceProvider;
use Illuminate\Support\Facades\Log;

class DataBaseQueryLoggerServiceProvider extends ServiceProvider
{
    /**
     * Register services.
     *
     * @return void
     */
    public function register()
    {
        //
    }

    /**
     * Bootstrap services.
     *
     * @return void
     */
    public function boot()
    {
        if ($this->app->environment("local")) {
            \DB::listen(function ($query) {
                \Log::info($query->sql);
                \Log::info($query->bindings);
            });
        }
    }
}

```

これでSQLクエリがログに流れます。SQLログを出すのは開発環境だけのことが多いので、

```app/Providers/DataBaseQueryLoggerServiceProvide.php
if ($this->app->environment("local")) {
```

上記のif文でログを出す条件を加えています。
ログは以下のように出てきます。

```shell
[2021-11-15 18:32:28] local.INFO: select * from `admin_users` where `user_id` = ? limit 1
```

これでSQLは確認できるようになりましたが、いくつか問題があると思います。
- ログが実行可能なSQL形式じゃない。
- 他のログにSQLログが混ざる。
- どの機能から実行されたSQLなのかわからない。

本記事では、これらの課題を解決を解決してきたいと思います。

# 1. ログを実行可能なSQLに成形する

このようにログを実行可能なSQLに整形します。

```app/Providers/DataBaseQueryLoggerServiceProvide.php
   public function boot()
    {
        if ($this->app->environment("local")) {
            \DB::listen(function ($query) {
                $sql = $query->sql;
                foreach ($query->bindings as $binding) {
                    if (is_string($binding)) {
                        $binding = "'{$binding}'";
                    } elseif (is_bool($binding)) {
                        $binding = $binding ? '1' : '0';
                    } elseif (is_int($binding)) {
                        $binding = (string) $binding;
                    } elseif ($binding === null) {
                        $binding = 'NULL';
                    } elseif ($binding instanceof Carbon) {
                        $binding = "'{$binding->toDateTimeString()}'";
                    } elseif ($binding instanceof DateTime) {
                        $binding = "'{$binding->format('Y-m-d H:i:s')}'";
                    }
                    $sql = preg_replace('/\\?/', $binding, $sql, 1);
                }
                \Log::info($sql);
            });
        }
    }
```

出力されるログは、次のようになります。

```shell
[2021-11-15 18:53:12] local.INFO: select * from `admin_users` where `user_id` = 'takada_yuki' limit 1
```

これで、実行できるSQLクエリがログに出るようになりました。

# 2. ログファイルを分離する

`config/logging.php` を編集することで、ログ周りに様々な設定を入れることができます。
channels配列にsqlチャンネルを追加してあげます。

```config/logging.php
    'channels' => [
        //
        'sql' => [
            'driver' => 'driver',
            'path' => storage_path('logs/laravel-sql.log'),
            'level' => 'debug',
            'days' => 14,
        ],
        //
    ],
```

先程作成したプロバイダーで出力するログのチャンネルを指定します。

```app/Providers/DataBaseQueryLoggerServiceProvide.php
    public function boot()
    {
        if ($this->app->environment("local")) {
            \DB::listen(function ($query) {
                $sql = $query->sql;
                foreach ($query->bindings as $binding) {
                    if (is_string($binding)) {
                        $binding = "'{$binding}'";
                    } elseif (is_bool($binding)) {
                        $binding = $binding ? '1' : '0';
                    } elseif (is_int($binding)) {
                        $binding = (string) $binding;
                    } elseif ($binding === null) {
                        $binding = 'NULL';
                    } elseif ($binding instanceof Carbon) {
                        $binding = "'{$binding->toDateTimeString()}'";
                    } elseif ($binding instanceof DateTime) {
                        $binding = "'{$binding->format('Y-m-d H:i:s')}'";
                    }
                    $sql = preg_replace('/\\?/', $binding, $sql, 1);
                }
                \Log::channel('sql')->info($sql);
            });
        }
    }
```

これで、storage/logs配下に、SQLログだけのログファイルが生成されます。

# 3. SQLを実行した機能を出力する

クエリの内容から大体どの機能(URL)から実行されたか推測は可能ですが、割とダルいです。
LaravelにはURLでアクセスされた場合定義してあるルート名を取得することができます。
※ routeに名前をつけるのがどんな機能か知りたい方は[こちら](https://qiita.com/kazuhei/items/935257b0d72fa314d461)をどうぞ。

こう変えてみます。

```app/Providers/DataBaseQueryLoggerServiceProvider.php
    public function boot()
    {
        if ($this->app->environment("local")) {
            \DB::listen(function ($query) {
                $route = 'NOT URL';
                if (method_exists(\Request::route(), 'getName')) {
                    $route = \Request::route()->getName();
                }
                $sql = $query->sql;
                foreach ($query->bindings as $binding) {
                    if (is_string($binding)) {
                        $binding = "'{$binding}'";
                    } elseif (is_bool($binding)) {
                        $binding = $binding ? '1' : '0';
                    } elseif (is_int($binding)) {
                        $binding = (string) $binding;
                    } elseif ($binding === null) {
                        $binding = 'NULL';
                    } elseif ($binding instanceof Carbon) {
                        $binding = "'{$binding->toDateTimeString()}'";
                    } elseif ($binding instanceof DateTime) {
                        $binding = "'{$binding->format('Y-m-d H:i:s')}'";
                    }
                    $sql = preg_replace('/\\?/', $binding, $sql, 1);
                }
                \Log::channel('sql')->info($route . PHP_EOL . $sql);
            });
        }
    }
```

URL以外からのアクセス(Command等)では
` \Request::route()->getName()` が使えない(500エラーに吸い込まれる）ので、
`if (method_exists(\Request::route(), 'getName'))`が必要です。

ログは次のように出てきます。

```shell
[2021-11-15 19:12:39] local.INFO: auth.login.post
select * from `admin_users` where `user_id` = 'takada_yuki' limit 1 
````
これで、どの機能から実行されたSQLなのかわかるようになりました。

# **分析が便利になるように整える**

こんな感じにしてみます。

```app/Providers/DataBaseQueryLoggerServiceProvider.php
   public function boot()
    {
        if ($this->app->environment("local")) {
            \DB::listen(function ($query) {
                $route = 'NOT URL';
                if (method_exists(\Request::route(), 'getName')) {
                    $route = \Request::route()->getName();
                }
                $sql = $query->sql;
                foreach ($query->bindings as $binding) {
                    if (is_string($binding)) {
                        $binding = "'{$binding}'";
                    } elseif (is_bool($binding)) {
                        $binding = $binding ? '1' : '0';
                    } elseif (is_int($binding)) {
                        $binding = (string) $binding;
                    } elseif ($binding === null) {
                        $binding = 'NULL';
                    } elseif ($binding instanceof Carbon) {
                        $binding = "'{$binding->toDateTimeString()}'";
                    } elseif ($binding instanceof DateTime) {
                        $binding = "'{$binding->format('Y-m-d H:i:s')}'";
                    }
                    $sql = preg_replace('/\\?/', $binding, $sql, 1);
                }
                \Log::channel('sql')->info('[ROUTE]' . $route );
                \Log::channel('sql')->info('[QUERY]' . $sql);
                \Log::channel('sql')->info('[TIME]' . "time(ms):{$query->time}" . PHP_EOL);
            });
        }
    }
```

出てくるログは以下のようになります。
適当なprefixを入れておくと、障害時の調査などの場面で役に立つと思います。

```sql
[2021-11-15 19:19:52] local.INFO: [ROUTE]auth.login.post  
[2021-11-15 19:19:52] local.INFO: [QUERY]select * from `admin_users` where `user_id` = 'takada_yuki' limit 1  
[2021-11-15 19:19:52] local.INFO: [TIME]time(ms):106.88
  
[2021-11-15 19:19:52] local.INFO: [ROUTE]top_page  
[2021-11-15 19:19:52] local.INFO: [QUERY]select * from `admin_users` where `id` = 1 limit 1  
[2021-11-15 19:19:52] local.INFO: [TIME]time(ms):148.01
```