概要
webアプリケーションを開発する際、アプリケーションが実行したSQLクエリの確認は欠かせません。ロギング周りの調整は開発の初期の段階でアプリケーションに仕込むことがほとんどだと思います。
今回は、LaravelでSQLログをいい感じに整形して出力する方法を紹介します。
サービスプロバイダを作る
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文でログを出す条件を加えています。
ログは以下のように出てきます。
[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);
});
}
}
出力されるログは、次のようになります。
[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に名前をつけるのがどんな機能か知りたい方はこちらをどうぞ。
こう変えてみます。
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'))が必要です。
ログは次のように出てきます。
[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を入れておくと、障害時の調査などの場面で役に立つと思います。
[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