はじめに

Laravel でモデルの 作成/更新/削除 を検知してログ出力する方法

TL;DR

  • bootXXXX を持つ trait を作成して、ログ取得したいモデルに設定
  • beginTransaction などのログも合わせて取得すると正確性が増す
  • クエリログも合わせて取得すると where()->update() のようなケースも取得できる
  • 要件/環境 によってはボトルネックになりかねないので注意が必要
この記事が参考になった方
ここかここからチャージや購入してくれると嬉しいです(ブログ主へのプレゼントではなく、ご自身へのチャージ)
欲しいもの / Wish list

目次

  1. はじめに
  2. TL;DR
  3. 環境・条件
  4. 詳細
    1. 設定方法
    2. 注意事項
      1. オーバーヘッドの考慮
      2. クエリビルダの update などは検知できない
      3. rollback しても出力される
  5. まとめ
  6. 参考文献

環境・条件

1
2
3
4
5
6
7
8
9
10
11
12
$ cat /etc/os-release
PRETTY_NAME="Ubuntu 16.04.6 LTS"

$ php -v
PHP 7.3.16-1+ubuntu16.04.1+deb.sury.org+1 (cli) (built: Mar 20 2020 13:51:21) ( NTS )

$ composer -V
Composer version 1.9.1 2019-11-01 17:20:17

$ composer info laravel/framework
name     : laravel/framework
versions : * v5.7.28

詳細

参考: [Laravel] Eloquentモデルのイベントをフックする4つの方法 | Xzxzyzyz

上記記事の4番目の方法を参考にした。(typo などがあり、そのままコピペしても動かなかったので注意)

設定方法

app/Http/Traits/ModelLogger.php: 新規作成

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
<?php

namespace App\Http\Traits;

use Illuminate\Support\Facades\Log;

trait ModelLogger
{
  protected static function bootModelLogger()
  {
    self::created(function ($model) {
      $class = get_class($model);
      Log::info("Created '{$class}': {$model}");
    });

    self::updated(function ($model) {
      $class = get_class($model);
      Log::info("Updated '{$class}': {$model}");
    });

    self::deleted(function ($model) {
      $class = get_class($model);
      Log::info("Deleted '{$class}': {$model}");
    });
  }
}

app/Hoge.php などのログ出力したいモデルに ModelLogger に関する記述を追加

1
2
3
4
5
6
7
8
9
10
11
12
<?php

namespace App;

use App\Http\Traits\ModelLogger;
use Illuminate\Database\Eloquent\Model;  // *****

class Hoge extends Model
{
  use ModelLogger;  // *****
  // 略
}

以下のようなログが出力されるようになる。

1
2
3
[2020-08-19 18:36:40] local.INFO: Created 'App\Hoge': {"name":"fuga","updated_at":"2020-08-19 18:36:40","created_at":"2020-08-19 18:36:40","id":1}
[2020-08-19 18:36:56] local.INFO: Updated 'App\Hoge': {"id":1,"name":"piyo","created_at":"2020-08-19 18:36:40","updated_at":"2020-08-19 18:36:56"}
[2020-08-19 18:37:22] local.INFO: Deleted 'App\Hoge': {"id":1,"name":"piyo","created_at":"2020-08-19 18:36:40","updated_at":"2020-08-19 18:37:14"}

注意事項

オーバーヘッドの考慮

同時利用者数が多い、モデルの 作成/更新/削除 の頻度が高いなどの場合、ログ出力による影響(CPU, Disk, etc)もバカにならないはずなので、利用時には注意すること。

クエリビルダの update などは検知できない

Hoge::where('id', '<', 10)->update(...) など、モデルを取得せずに処理するようなものは検出できない。

1
2
3
4
5
Hoge::create();            // OK
Hoge::find()->update();    // OK
Hoge::find()->delete();    // OK
Hoge::where()->update();   // NG
Hoge::where()->delete();   // NG

合わせて QueryExecuted イベントに対して以下を設定すると、SQL のログは出力可能。
(だが、実際に 更新/削除 されたデータの具体的な情報などは分からない)

app/Providers/EventServiceProvider.php

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
<?php

namespace App\Providers;

use App\Listeners\QueryLogger;  // *****
use Illuminate\Support\Facades\Event;
use Illuminate\Database\Events\QueryExecuted;  // *****
use Illuminate\Foundation\Support\Providers\EventServiceProvider as ServiceProvider;

class EventServiceProvider extends ServiceProvider
{
  protected $listen = [
    // 略
    QueryExecuted::class => [
      QueryLogger::class,
    ],
  ];
  // 略
}

app/Listeners/QueryLogger.php

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
<?php

namespace App\Listeners;

use Carbon\Carbon;
use DateTime;
use Illuminate\Queue\InteractsWithQueue;
use Illuminate\Contracts\Queue\ShouldQueue;
use Illuminate\Support\Facades\Log;

class QueryLogger
{
  public function handle($event)
  {
    $sql = $event->sql;
    // select などは除外
    if (!preg_match('/^(insert|update|delete)/', $sql)) {
      return;
    }

    foreach ($event->bindings as $binding) {
      if (is_string($binding)) {
        $binding = "'{$binding}'";
      } elseif (is_bool($binding)) {
        $binding = $binding ? '1' : '0';
      } 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', ['sql' => $sql, 'time' => "$event->time ms"]);
  }
}

rollback しても出力される

あくまでも create, update, delete などのイベント検知時のログ出力なので、たとえ DB::rollback() で実際にはレコードが保存されなかった場合でもログは残ったままとなる。

TransactionBeginning, TransactionCommitted, TransactionRolledBack のイベントもログ出力すると、実際に保存されたのかどうかもあわせて確認できるようになる。
(が、当然その分ログ出力量が増加するので注意)

app/Providers/EventServiceProvider.php

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
<?php

namespace App\Providers;

use App\Listeners\TransactionBeginLogger;
use App\Listeners\TransactionCommitLogger;
use App\Listeners\TransactionRollbackLogger;
use Illuminate\Support\Facades\Event;
use Illuminate\Database\Events\TransactionBeginning;
use Illuminate\Database\Events\TransactionCommitted;
use Illuminate\Database\Events\TransactionRolledBack;
use Illuminate\Foundation\Support\Providers\EventServiceProvider as ServiceProvider;

class EventServiceProvider extends ServiceProvider
{
  protected $listen = [
    // 略
    TransactionBeginning::class => [
      TransactionBeginLogger::class,
    ],
    TransactionCommitted::class => [
      TransactionCommitLogger::class,
    ],
    TransactionRolledBack::class => [
      TransactionRollbackLogger::class,
    ],
  ];
  // 略
}

TransactionXXXXLogger

1
2
3
4
5
6
7
8
9
10
11
12
13
14
<?php

namespace App\Listeners;

use Illuminate\Queue\InteractsWithQueue;
use Illuminate\Contracts\Queue\ShouldQueue;

class TransactionBeginLogger
{
  public function handle($event)
  {
    \Log::info("Begin Transaction");
  }
}

まとめ

  • bootXXXX を持つ trait を作成して、ログ取得したいモデルに設定
  • beginTransaction などのログも合わせて取得すると正確性が増す
  • クエリログも合わせて取得すると where()->update() のようなケースも取得できる
  • 要件/環境 によってはボトルネックになりかねないので注意が必要

参考文献

関連記事

この記事が参考になった方
ここかここからチャージや購入してくれると嬉しいです(ブログ主へのプレゼントではなく、ご自身へのチャージ)
欲しいもの / Wish list