🌻

DatadogでLaravelアプリケーションを監視する

のりぃ

2020/12/09に公開

この記事は、OPENLOGI Advent Calendar 2020 9日目の記事です。

本日は、嫁に「のりぃは30歳」という呪いをかけられた、昭和49年生まれの @m_norii が担当します。

私は、OPENLOGIに2020年1月に入社しました。
もうすぐ丸一年ですね。

OPENLOGIでは、主にインフラ周り、AWSやBigQueryあたりを扱っています。

本日は、最近社内で評価し始めた、監視基盤SaaSの Datadog について、特にPHPフレームワークであるLaravelアプリケーションに導入する上でのポイントを紹介します。

この記事の内容は以下の環境で検証しています。

OS、ミドルウェア等	バージョン
Ubuntu	18.04
Datadog Agent	7.23.1
Datadog PHP Tracer（DDTrace）	0.50.0
PHP	7.2.24
Laravel	7.12.0
Supervisor	3.3.1

基本的な導入方法

Datadog Agent、および PHP APM用のトレーサーである DDTrace拡張をインストールします。

https://docs.datadoghq.com/ja/agent/

これだけで、基本的なメトリクスやトレースデータの取得ができます。

PHPの場合、Laravel、Symfony、CakePHP等の主要なフレームワークについては、Datadog の PHP Tracerの機能で、よしなにデータ収集をしてくれます。

さらに、いくつかアプリケーション側のソースコードに手を入れることで
Datadogをより便利に利用することができます。

カスタムタグの追加

APMのトレース情報に、アプリケーション由来の情報を紐付けておくと便利なことがあります。
たとえば、アプリケーション側で持っているユーザIDを紐付けると
Datadog UIで、そのユーザに絞り込んで表示することができます。

Laravelでこれを実現する場合、Web経由でのアクセスに対して横断的に処理を噛ませたいので
こういう用途では、(HTTP)Middleware がよいと思います。

app/Http/Middleware/Datadog.php

<?php
namespace App\Http\Middleware;

use Closure;
use Illuminate\Http\Request;
use DDTrace\GlobalTracer;

class Datadog
{
    /**
     * @return mixed
     */
    public function handle(Request $request, Closure $next)
    {
        $response = $next($request);

        $span = GlobalTracer::get()->getActiveSpan();
        if ($span === null) {
            return $response;
        }
        $user = $request->user();
        if ($user) {
            $span->setTag('userId', $user->id);
        }

        return $response;
    }
}

このMiddlewareを app/Http/Kernel.php で読み込むようにします。

app/Http/Kernel.php

<?php
namespace App\Http;

use Illuminate\Foundation\Http\Kernel as HttpKernel;

class Kernel extends HttpKernel
{
    /**
     * The application's global HTTP middleware stack.
     *
     * @var array
     */
    protected $middleware = [
        \App\Http\Middleware\Datadog::class,
    ];
// (以下略)
}

これで、Datadog上のTraceに、ユーザIDを紐付けることができます。

参考：公式ドキュメント

laravel.log を Datadog に送る

Laravelが出力するログをDatadog Logsに送る設定です。
まず、Datadog Agentのメイン設定ファイル（datadog.yaml）で、ログ収集を有効化します。
デフォルトは無効なので、logs_enabledを検索して、true に変更します。

/etc/datadog-agent/datadog.yaml

logs_enabled: true

次にlaravel.logをDatadogに送るための設定ファイルを作成します。
datadog.yamlと同じ階層にconf.dディレクトリがあるので、その中にphp.dディレクトリを作り
conf.yaml を作成します。

/etc/datadog-agent/conf.d/php.d/conf.yaml

init_config:

instances:

## Log section
logs:

  - type: file
    path: "/path/to/laravel.log"
    service: php
    source: php
    sourcecategory: sourcecode

ここで、Datadogのドキュメントにもあるのですが、Datadogではログの形式として、jsonフォーマットを推奨しています。
またDatadog以外の観点でも、json形式にしておいたほうがプログラム等で取り回ししやすいので、これから設定するのであれば、json形式がよいでしょう。

ですがLaravelのデフォルトでは、singleという、シングルファイル・パスベースのdriverが設定されています。

もともとこの形式でログを出力していて、json形式に変えられない場合もあるかと思います。
この single driverを使う場合は以下のように設定を追加します。

/etc/datadog-agent/conf.d/php.d/conf.yaml

init_config:

instances:

## Log section
logs:

  - type: file
    path: "/path/to/laravel.log"
    service: php
    source: php
    sourcecategory: sourcecode
    log_processing_rules:
       - type: multi_line
         name: new_log_start_with_date
         pattern: \[\d{4}\-(0?[1-9]|1[012])\-(0?[1-9]|[12][0-9]|3[01])

log_processing_rules は、このログファイルがどんな形式かをAgentに知らせるためのオプションです。
Laravel logging の single driverでは、１つのログ出力が複数行にまたがることがあるので
複数行ログを処理できるように、ログエントリの区切り（[YYYY-MM-DDで始まる）をこの設定でAgentに伝えます。

参考：公式ドキュメント

laravel.log に Datadog トレースID等を埋め込む

laravel.log に Datadogが管理するトレースIDおよびスパンIDを埋め込むと
Datadog UI上で、トレース情報に関連するログが紐付いて表示されるようになります。

トレースとスパンという言葉がいきなりでてきましたが、詳細な説明は用語集を見ていただくとして
ざっくりいうと、
トレースは「リクエストを受け付けてレスポンスを返すまで」
スパンは「トレースの中の作業単位」
となっています。

このログにトレースIDを埋め込む方法は、以下のDatadogドキュメントに参考実装があります。

が、ちょっとこの参考実装はあまり筋がよくないなと思っていまして
Laravelのドキュメントによると、ServiceProvider::register() メソッドは サービスコンテナに何かを結合することだけを行わなければなりません。 とあります。

なので、この用途であれば、同クラスの boot() メソッドに実装・・・でもいいのですが
ここは、そもそもLogに対してカスタム実装を入れたい、ということなので
Laravel Wayに則るならば、Monologチャンネルをカスタマイズする方針がよさそうです。

ここでも引き続き single log driver の例で話を進めます。
（jsonの場合でも、Datadogのサンプルにある実装の中身を、この方法に置き換えればうまくいくと思います。）

まず、Monologインスタンスをカスタマイズするクラスを実装します。

app/Logging/DatadogFormatter.php

<?php
namespace App\Logging;

use Illuminate\Log\Logger;

class DatadogFormatter
{
    /**
     * APMで出力されたTraceIdをログへ追加
     *
     * @param  Logger  $logger
     *
     * @return void
     */
    public function __invoke(Logger $logger)
    {
        foreach ($logger->getHandlers() as $handler) {
            $handler->pushProcessor(function ($record) {
                $span = \DDTrace\GlobalTracer::get()->getActiveSpan();
                if ($span === null) {
                    return $record;
                }

                $record['message'] .= sprintf(
                    ' [dd.trace_id=%d dd.span_id=%d]',
                    $span->getTraceId(),
                    \dd_trace_peek_span_id()
                );

                return $record;
            });
        }
    }
}

このクラスを、config/logging.php 内で tap配列に指定します。

config/logging.php

<?php

return [
//    (中略)
    'channels' => [
        'single' => [
            'driver' => 'single',
            'path' => storage_path('logs/laravel.log'),
            'level' => 'debug',
            'tap' => [App\Logging\DatadogFormatter::class],
        ],
//    (中略)
];

これで、laravel.log に、トレースID、スパンIDが追加され
Datadog上で、APM TraceとLogを連携して見れるようになります。

参考：公式ドキュメント

ログレベルをDatadog UIに反映する

ここでも引き続き single log driver を利用している場合の話です。
(jsonの場合は、statusパラメータとしてログレベルを出力すれば、Datadogのデフォルトの設定で自動的に認識します)

今までの設定で、laravel.log が Datadog UI上で見れるようになったのですが
LogのStatusが一律デフォルトのInfoになっていて、Errorなどの識別ができていません。

そこで、Datadog Logsの設定で、PerserとRemapperを設定します。
Datadogのメニューから Logs > Configuration とたどります。

Add a new pipeline で新規パイプラインを作成し
まず Grok Parser 内 Define parsing rules で、以下の設定で追加します。

monolog_rule \[%{date("yyyy-MM-dd HH:mm:ss","Asia/Tokyo"):date}\]\s+%{word:env}.%{word:level}:\s+%{data:message}(\s+\[%{data::keyvalue}\])?

次に Status Remapper を追加し Set status attribute(s) に level を設定します。

Grok ParserとStatus Remapperを追加したところ

これで、ログレベルのラベリングが正しくマッピングされます。

参考：公式ドキュメント

コマンドラインで実行するスクリプトのトレース

ここまでの設定で、だいぶ有益な情報がとれるようになってきました。
しかし、この設定ではまだDatadogで取れない情報があります。
それはコマンドラインから実行した処理です。

Laravelだと、タスクスケジュールやキューワーカーで実行される非同期ジョブが該当します。

Datadogでは、デフォルトではコマンドラインからの実行では、Agentの処理は実行されません。
コマンドラインからの実行も、Agentの処理を通してDatadogへメトリクス等を送りたい場合
環境変数 DD_TRACE_CLI_ENABLED=true を設定する必要があります。

たとえば、単発で実行するartisan コマンドなら以下のように実行します。

$ DD_TRACE_CLI_ENABLED=true php artisan some:command

参考：公式ドキュメント

タスクスケジュール

タスクスケジュールで実行される処理のトレース情報をDatadogへ送りたい場合は
crontab にて環境変数を設定するのが一番楽かと思います。

DD_TRACE_CLI_ENABLED=true
* * * * * cd /path/to/your/project && php artisan schedule:run >> /path/to/your/logs/task-schedule.log 2>&1

キューワーカーによる非同期ジョブ

キューワーカーによる非同期ジョブをトレースするようにするには、一工夫必要になります。
というのも、単に環境変数 DD_TRACE_CLI_ENABLED=true を渡しただけだと
php artisan queue:work で起動するプロセスをトレースしますが
このプロセス自体は、単にキューされたジョブをデキューして実行・・・をひたすら繰り返しているだけのもので
これのトレース情報を得てもあまり有益な情報はありません。
本当にほしいのは、 ワーカーがデキューして実行したジョブ のトレース情報ですよね。

これを実現するために、以下の追加設定が必要です。

環境変数 DD_TRACE_GENERATE_ROOT_SPAN, DD_TRACE_AUTO_FLUSH_ENABLEDの追加
トレースの起点となるメソッドを Datadog APMに登録する

環境変数の追加

キューワーカーの起動時に、以下の２つの環境変数を追加します。

DD_TRACE_GENERATE_ROOT_SPAN=false
- 通常は自動で生成されるトップレベルのスパンを生成しないようにします。php artisan queue:work 自体のスパンを作らないようにするためです。
DD_TRACE_AUTO_FLUSH_ENABLED=true
- すべてのスパンが終了したら、トレーサーをFlushします

参考：公式ドキュメント、および関連PullRequest

この環境変数を設定する場所ですが、Laravelで非同期ジョブの機能を使う場合
なんらかのdeamonizeなミドルウェア、Laravelドキュメントに記載されているところでいうと
Supervisorなどを使われているかと思います。

Supervisorの設定では

/etc/supervisor/supervisord.conf

[program:laravel-worker]
process_name=%(program_name)s_%(process_num)02d
command=php /home/forge/app.com/artisan queue:work sqs --sleep=3 --tries=3

のように書きますが、このcommandの指定内では、環境変数を設定できません。

/etc/supervisor/supervisord.conf

# ダメな例
command=DD_TRACE_CLI_ENABLED=true DD_TRACE_GENERATE_ROOT_SPAN=false DD_TRACE_AUTO_FLUSH_ENABLED=true php /home/forge/app.com/artisan queue:work sqs --sleep=3 --tries=3

Supervisor経由で起動するプロセスに環境変数を渡したい場合は
environmentの項に指定する必要があります。

/etc/supervisor/supervisord.conf

[program:laravel-worker]
process_name=%(program_name)s_%(process_num)02d
command=php /home/forge/app.com/artisan queue:work sqs --sleep=3 --tries=3
environment=DD_TRACE_CLI_ENABLED=true,DD_TRACE_GENERATE_ROOT_SPAN=false,DD_TRACE_AUTO_FLUSH_ENABLED=true

定義しているワーカーの数が多い場合は、supervisord セクションに書くと全ワーカーに環境変数を設定できます。

/etc/supervisor/supervisord.conf

[supervisord]
# (中略)
environment=DD_TRACE_CLI_ENABLED=true,DD_TRACE_GENERATE_ROOT_SPAN=false,DD_TRACE_AUTO_FLUSH_ENABLED=true

トレースの起点となるメソッドを Datadog APMに登録

さらに、トレースの起点となるメソッドを、Datadog APMに登録する必要があります。
この登録には、Datadog AgentであるPHP拡張 ddtrace に定義されている \DDTrace\trace_method() 関数を利用します。

そもそも、Datadog Agentと APM（ddtrace）をセットアップした際
Datadog APM Traceを眺めていると、laravel.requestとかeloquent.get という名称が流れてきますが
これは何かというと、Datadog APMが利用しているフレームワークに応じて、自動的にいくつかのメソッドを
\DDTrace\trace_method() 関数を使ってAPMへ登録しているのです。
そのソースはこのあたり(Laravel Integration, Eloquent Integration)で確認できます。

これと同じ要領で、非同期ジョブを実行しているメソッドを\DDTrace\trace_method() 関数で登録します。

さて、ではこの「非同期ジョブを実行しているメソッド」とは具体的にどこでしょう？

これには、そもそも、Laravelのジョブディスパッチの仕組みを理解する必要があります。
この仕組みについては以下エントリが詳しいです。

「Queueの処理を理解する」のセクションの最後の方に登場する
Illuminate\Queue\CallQueuedHandler::call() メソッドがそれです。
これを \DDTrace\trace_method() 関数に渡します。

では、\DDTrace\trace_method() はどこで設定すべきか？
これは、アプリケーションが処理される際には常に登録しておきたいので、
ServiceProviderを継承したクラスのboot() メソッドが良いでしょう。
デフォルトで用意されている AppServiceProviderでもいいのですが
Datadog専用に ServiceProvider を作ってしまったほうが見通しがいいかと思います。

app/Providers/DatadogServiceProvider.php

<?php
namespace App\Providers;

use Illuminate\Queue\CallQueuedHandler;
use Illuminate\Support\ServiceProvider;

class DatadogServiceProvider extends ServiceProvider
{
   /**
     * Bootstrap services.
     *
     * @return void
     */
    public function boot()
    {
        \DDTrace\trace_method(
            CallQueuedHandler::class,
            'call',
            function (\DDTrace\SpanData $span, array $args) {
                $span->service = 'queue-worker';
                $span->name = 'laravel.queue.work';
                $span->resource = $args[1]['commandName'];
            }
        );
    }
}

$args[1]['commandName'] の箇所について補足します。
$args には、\DDTrace\trace_method() で登録した Illuminate\Queue\CallQueuedHandler::call() の引数が配列で渡ってきます。
このシグネチャは public function call(Job $job, array $data) です(参考： GitHub上のソース)。
この第2引数、array $data は、ジョブのペイロードです(参考： GitHub上のソース)。
この配列のcommandNameにジョブのクラス名が格納されているので、これをDatadog上で表示されるリソース名として登録しています。

そして、この DatadogServiceProvider を起動時に読み込むように
config/app.php の providers 配列に追加します。

config/app.php

<?php
// (中略)
    'providers' => [
        // (中略)
        App\Providers\DatadogServiceProvider::class,
    ],
// (中略)

これで、キューワーカーによる非同期ジョブ実行も、Datadog上でトレースできるようになります。

余談ですが、ここで作ったDatadogServiceProviderは
Web経由でもCLI経由でもかならず処理されるので、
Web/CLIどちらでも設定したいカスタムタグを書く場所としても利用できます。
たとえば、 version タグを設定すれば、 Datadogのデプロイメント追跡に利用できます。

app/Providers/DatadogServiceProvider.php

    public function boot()
    {
        // (中略)
    
        $span = \DDTrace\GlobalTracer::get()->getActiveSpan();
        if ($span !== null) {
	    // 別途、環境変数VERSIONにGitのタグやコミットハッシュを設定しておく
            $span->setTag('version', env('VERSION'));
        }
    }

おわりに

DatadogでLaravelアプリケーションを監視する方法をご紹介しました。
ここにある内容は、Web上の様々なリソースに点在してはいたのですが
「じゃあ、そもそもLaravelアプリケーションではどう設定すればいいのさ！もっと一気通貫で教えてくれ！」
という思いから、どなたかの役に立てばと思い、記事にしました。
ご参考になれば幸いです。

OPENLOGI Tech BlogPublication

私たちは身近な社会課題である物流の未来を変えるべく、「物流版AWS」をコンセプトとしたプラットフォームの開発、データの活用によって、業界全体の最適化を目指す会社です。

基本的な導入方法

カスタムタグの追加

laravel.log を Datadog に送る

laravel.log に Datadog トレースID等 を埋め込む

ログレベルをDatadog UIに反映する

コマンドラインで実行するスクリプトのトレース

タスクスケジュール

キューワーカーによる非同期ジョブ

環境変数の追加

トレースの起点となるメソッドを Datadog APMに登録

おわりに

Discussion

laravel.log に Datadog トレースID等を埋め込む