php + php-fpm + nginx のDatadog APM設定でハマった話

前提

DatadogのAPMでphpのアプリケーションログを取得したい。
環境はちとレガシー。

環境

項目	詳細
環境	VMWare
OS	CentOS 6.8
言語	PHP 5.6.40
ミドルウェア	PHP-FPM 5.6.40 , Nginx/1.11.1
APM	Datadog 7.17.1

手順

基本的には 本家のPHP APMのページを の通りに実施。

事象

DatadogのAPMに全くログが表示されない。。。

/var/log/datadog/trace-agent.logを見るにたまに中身が入っていないログが出てましたが、
これはdd-doctor.phpを実行した際に出力されるもののようでした。

原因

dd-trace-phpからdatadogのtrace-agentへの通信に異様に時間がかかり、タイムアウトしてしまう。
ちなみにCentOS7以降であれば大丈夫そうでした。

おま環はありそう。

動作や設定確認

環境構築が終わった後の動作確認。
とりあえず一通り問題なし。

phpのmodule

$ php -m | grep ddtrace
ddtrace

$ php --ri=ddtrace

ddtrace

Datadog PHP tracer extension
For help, check out the documentation at https://docs.datadoghq.com/tracing/languages/php/
(c) Datadog 2019

Datadog tracing support => enabled
Version => 0.40.0

Directive => Local Value => Master Value
ddtrace.disable => Off => Off
ddtrace.internal_blacklisted_modules_list => ionCube Loader,newrelic, => ionCube Loader,newrelic,
ddtrace.request_init_hook => /opt/datadog-php/dd-trace-sources/bridge/dd_wrap_autoloader.php => /opt/datadog-php/dd-trace-sources/bridge/dd_wrap_autoloader.php
ddtrace.strict_mode => Off => Off

Datadog trace-agentが動いているか

$ netstat -anp | grep 8126
tcp 0 0 127.0.0.1:8126 0.0.0.0:* LISTEN 30926/trace-agent

$ lsof -i:8126
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
trace-age 30926 dd-agent 6u IPv4 131873793 0t0 TCP vm-cent6:8126 (LISTEN)

$ curl localhost:8126
404 page not found

dd-doctor.phpの結果もオールグリーン

DataDog trace extension verification

- PHP version and SAPI                               [5.6.25 - fpm-fcgi]
- ddtrace extension installed                        [OK]
- ddtrace version (installed)                        [0.40.0]
- ddtrace version (const)                            [0.40.0]
- ddtrace version (userland)                         [0.40.0]
- ddtrace versions in sync                           [OK]
- dd_trace() function available                      [OK]
- dd_trace_env_config() function available           [OK]
- ddtrace.request_init_hook set                      [OK]
- ddtrace.request_init_hook reachable                [OK]
- ddtrace.request_init_hook has run                  [OK]
- 'open_basedir' allows access to '/proc/self/'      [OK]
- IntegrationsLoader exists                          [OK]
- Integrations not loaded yet                        [OK]
- Registering an autoloader...
- Integrations loaded                                [OK]
- DDTrace\Tracer class exists                        [OK]
- Background sender is enabled?                      [YES]
- Configured Agent host                              [localhost]
- Configured Agent port                              [8126]
- Agent can receive traces                           [OK]

trace-agent.logを見るとたまに下記のようなアクセス来てるっぽいログが残っているけどアプリケーション情報的なものが入って無さそう。

$ less /var/log/datadog/trace-agent.log
| TRACE | INFO | (pkg/trace/info/stats.go:101 in LogStats) | No data received
| TRACE | INFO | (pkg/trace/info/stats.go:108 in LogStats) | [] -> traces received: 0, traces filtered: 0, traces amount: 4 bytes, events extracted: 0, events sampled: 0

tcpdumpを見てもtrace-agentに通信が来ている様子はなし。

$ tcpdump -i lo -nn port 8126
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes

下記のissueを参考にcurlでtrace-agentに擬似的なデータを流してみます。

$ curl localhost:8126/v0.4/traces \
    -X POST \
    -H 'Content-Type: application/json' \
    -d '[[{"span_id":7888852067085145860,"trace_id":8410276558263903151,"parent_id":0,"name":"symfony.request","service":"some_service","type":"web","resource":"/","start":1568281716000000000,"duration":265471}]]'

これを実施した感じだとtrace-agentに通信がいっているようでちょっと待ったらDatadogのWebコンソールにもアプリケーションログが出てきました。
trace-agent側は問題無さそうで通信がいけば飛びそうだなー

デバッグログの確認

とりあえずデバッグログを出すようにして確認。
Nginxにfastcgi_paramsで設定追加。

Tracing PHP Applications - Configuration - NGINX

fastcgi_param  DD_TRACE_ENABLED true;

その後、Nginxとphp-fpmを再起動。
デバッグログはNginxのerror.logの設定に従って出力されています。

下記の通りのエラーが出力されている。

PHP message: [2020-03-02T10:58:25+09:00] [ddtrace] [error] - Reporting of spans failed: 28 / Timeout was reached (TIMEOUT_MS=1000, CONNECTTIMEOUT_MS=500)
PHP message: [2020-03-02T10:58:25+09:00] [ddtrace] [error] - * Closing connection #0
* Timeout was reached" while reading upstream, client: xxx.xxx.xxx.xxx, server: dd-test.com, request: "GET /info.php HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "dd-test.com"

タイムアウトになっているっぽい。。。
(ちなみにTIMEOUT_MSはデフォルト100(ms)だったのを1000にしていましたがタイムアウトしてました)

タイムアウト値を延ばしてみる

fastcgi_param DD_TRACE_AGENT_CONNECT_TIMEOUT 10000;
fastcgi_param DD_TRACE_AGENT_TIMEOUT 10000;

| TRACE | INFO | (pkg/trace/info/stats.go:108 in LogStats) | [lang:php lang_version:5.6.25 interpreter:fpm-fcgi tracer_version:0.40.0] -> traces received: 2, traces filtered: 0, traces amount: 359761 bytes, events extracted: 2, events sampled: 2

あー、なんかそれっぽいの飛んだ。
tcpdumpにも反応が見えました！！
DatadogのWebコンソールからもアプリケーションログが確認できましたー

という事でタイムアウト値を延ばす事で対応できました
タイムアウト値自体は適切な値を検証する必要がありそうですが。

わかって見ればなんて事のない事象でしたが初めてのAPM導入という事もあり、けっこうハマっちゃいました

ちなみに

つい先日リリースされたdd-trace-phpの0.41.0には DD_TRACE_BETA_SEND_TRACES_VIA_THREAD というオプションが追加されてました。

これを有効にすると trace-agentへの通信をバックグラウンドで実行してくれて、タイムアウト値を調整せずとも今回のような事象を解消してくれるようです。

DataDog/dd-trace-php

なんかめちゃくちゃタイムリーというか、issueには見当たらなかったけどけっこう要望があったのだろうか。

タイムアウト値を不要に延ばすよりはこっちのオプションで対応がスマートなのかなー
オプション名にめちゃめちゃBETAって付いているのが気になりますが。

と思っていたら このプルリク を見る限りはGAになった時に DD_TRACE_BGS_ENABLED に置き換えられるのかな。