nginxログをFluentdとNew Relicで見える化する

こんにちは、マネージドサービス部大城です。

リバースプロキシ（今回の場合nginx）のログをNew Relic Logsに連携して見える化してみます。

New Relic APMを入れたらデフォルトでログが自動転送されるので便利です。APMが対応している言語であればAPMを入れるのが手っ取り早いです。

ただ、APMが対応していない言語やアプライアンス製品などAPMを入れるのが難しい環境は、リバースプロキシ（今回の場合nginx）があればログをNew Relic Logsに連携することである程度見える化することができます。制限がある環境で見える化したい場合の参考にしてください。

環境準備
やってみた
さいごに

環境準備

今回もisucon13の再現環境を利用させていただきました。前回のブログの内容でAWS環境にオールインワンを構築します。

sshした後に「isucon」ユーザーにスイッチします。ターミナル上は基本的に「isucon」ユーザーで操作することになります。言語はpythonを使うので切り替えておきます。

sudo -i -u isucon
sudo systemctl disable --now isupipe-go.service
sudo systemctl enable --now isupipe-python.service

やってみた

Fluentdのインストール

Before Installation を参照してカーネルパラメータなどを設定します。

今回の環境はある程度設定されていたので、追加設定は /etc/sysctl.conf のみでした。環境によって違いますのでよく読んでから設定してください。

sudo vi /etc/sysctl.conf

/etc/sysctl.conf

net.core.somaxconn = 1024
net.core.netdev_max_backlog = 5000
net.core.rmem_max = 16777216
net.core.wmem_max = 16777216
net.ipv4.tcp_wmem = 4096 12582912 16777216
net.ipv4.tcp_rmem = 4096 12582912 16777216
net.ipv4.tcp_max_syn_backlog = 8096
net.ipv4.tcp_slow_start_after_idle = 0
net.ipv4.tcp_tw_reuse = 1
net.ipv4.ip_local_port_range = 10240 65535
# If forward uses port 24224, reserve that port number for use as an ephemeral port.
# If another port, e.g., monitor_agent uses port 24220, add a comma-separated list of port numbers.
# net.ipv4.ip_local_reserved_ports = 24220,24224
net.ipv4.ip_local_reserved_ports = 24224

sysctlコマンドで反映させます。

sudo sysctl -p

Install by DEB Package (Debian/Ubuntu) を参照しFluentdをインストールします

curl -fsSL https://toolbelt.treasuredata.com/sh/install-ubuntu-jammy-fluent-package5-lts.sh | sh

Fluentd plugin for log forwarding を参照しNew Relicのプラグインをインストールします

sudo fluent-gem install fluent-plugin-newrelic

Fluentdの設定ファイルを作成します

sudo vi /etc/fluent/fluentd.conf

/etc/fluent/fluentd.conf

#Tail one or more log files
<source>
  @type tail
  <parse>
    @type none
  </parse>
  path /var/log/nginx/access.log
  tag example.service
</source>

#Add hostname and service_name to all events with "example.service" tag
<filter example.service>
  @type record_transformer
  <record>
    service_name ${tag}
    hostname "#{Socket.gethostname}"
  </record>
</filter>

#Forward all events to New Relic
<match **>
  @type newrelic
  license_key xxxxxxxxxxxxxxxxxxNRAL
</match>

Linux上のfluentdユーザーにnginxのログの読み取り権限を与えます

sudo chmod o+r /var/log/nginx/access.log

Fluentdを再起動します

sudo systemctl restart fluentd.service

この状態で負荷ツールを実行してログを流してみます。

cd
./bench run --enable-ssl

New Relic Logsにログが連携されました。

ログを構造化する

一旦は連携されるようになりましたが、もう少し工夫してみます。現在のNew Relic Logsの値は下の通りになっています。（不要な部分は削除しています）

New Relic Logsのデータ

{
  "hostname": "ip-10-200-1-171",
  "message": "127.0.0.1 - - [30/Apr/2024:09:42:30 +0000] \"GET /api/livestream/search?limit=50 HTTP/1.1\" 499 0 \"-\" \"isucandar\"",
  "service_name": "example.service",
  "timestamp": 1714470150618
}

この状態だと message に解析したい情報が集約されており、扱いにくいので分解して解析しやすいようにします。

nginxのログ形式を ltsv に変更します。

sudo vi /etc/nginx/nginx.conf

/etc/nginx/nginx.conf

# (不要な箇所は削除しています)
user www-data;
worker_processes auto;
pid /run/nginx.pid;
include /etc/nginx/modules-enabled/*.conf;

events {
    worker_connections 768;
}

http {
    sendfile on;
    tcp_nopush on;
    types_hash_max_size 2048;
    include /etc/nginx/mime.types;
    default_type application/octet-stream;
    ssl_protocols TLSv1 TLSv1.1 TLSv1.2 TLSv1.3; # Dropping SSLv3, ref: POODLE
    ssl_prefer_server_ciphers on;
    log_format ltsv 'time:$time_iso8601\t'
                    'remote_addr:$remote_addr\t'
                    'request_method:$request_method\t'
                    'request_length:$request_length\t'
                    'request_uri:$request_uri\t'
                    'https:$https\t'
                    'uri:$uri\t'
                    'query_string:$query_string\t'
                    'status:$status\t'
                    'bytes_sent:$bytes_sent\t'
                    'body_bytes_sent:$body_bytes_sent\t'
                    'referer:$http_referer\t'
                    'useragent:$http_user_agent\t'
                    'forwardedfor:$http_x_forwarded_for\t'
                    'request_time:$request_time\t'
                    'upstream_response_time:$upstream_response_time';
    access_log /var/log/nginx/access.log ltsv;
    error_log /var/log/nginx/error.log;
    gzip on;
    include /etc/nginx/conf.d/*.conf;
    include /etc/nginx/sites-enabled/*;
}

nginxを再起動します

sudo systemctl restart nginx.service

/etc/fluent/fluentd.conf の @type を none -> ltsv に修正します。この設定で key:value の形でパースして連携してくれます。

sudo vi /etc/fluent/fluentd.conf

/etc/fluent/fluentd.conf

#Tail one or more log files
<source>
  @type tail
  <parse>
    @type ltsv
  </parse>
  path /var/log/nginx/access.log
  tag example.service
</source>

#Add hostname and service_name to all events with "example.service" tag
<filter example.service>
  @type record_transformer
  <record>
    service_name ${tag}
    hostname "#{Socket.gethostname}"
  </record>
</filter>

#Forward all events to New Relic
<match **>
  @type newrelic
  license_key xxxxxxxxxxxxxxxxxxNRAL
</match>

sudo systemctl restart fluentd.service

この状態で再度ログ転送してみます

cd
./bench run --enable-ssl

New Relic Logs上のデータが key:value の形で構造化され解析しやすくなりました。

New Relic Logs上のデータ

{
  "body_bytes_sent": "57049",
  "bytes_sent": "57214",
  "forwardedfor": "-",
  "hostname": "ip-10-200-1-171",
  "https": "on",
  "query_string": "-",
  "referer": "-",
  "remote_addr": "127.0.0.1",
  "request_length": "720",
  "request_method": "GET",
  "request_time": "0.097",
  "request_uri": "/api/user/qsato1/icon",
  "service_name": "example.service",
  "status": "200",
  "timestamp": 1714470881000,
  "upstream_response_time": "0.100",
  "uri": "/api/user/qsato1/icon",
  "useragent": "isucandar"
}

この状態だと下のようなNRQLで集計することができます

StatusCode別の集計

FROM Log select count(*) facet status SINCE 10 minutes ago

リクエスト多いURI TOP10

FROM Log select count(*) facet request_uri
SINCE 10 minutes ago LIMIT 10

user_idをログに埋め込む

もう少し解析しやすいように、ログに user_id 情報を埋め込んでみます。

フレームワークによって方法が違いますが、今回Python、Flaskで試してみます。同じようなことは大体のフレームワークでもできると思います。

レスポンスヘッダーに userid 情報を埋め込むようにコード追加します。

参考

How to configure a Flask app to log user id and session id in nginx logs | by Surya Sankar | Medium

Flaskでヘッダー情報をafter_requestで設定する | kosh.dev

vi /home/isucon/webapp/python/app.py
# 下記を追加
@app.after_request
def after_request(response):
    response.headers['X-Userid'] = session.get(Settings.DEFAULT_USER_ID_KEY)
    return response

アプリを再起動します

sudo systemctl restart isupipe-python.service

nginxのログに upstream_http_x_userid を出力するよう設定します

sudo vi /etc/nginx/nginx.conf

/etc/nginx/nginx.conf

user www-data;
worker_processes auto;
pid /run/nginx.pid;
include /etc/nginx/modules-enabled/*.conf;

events {
    worker_connections 768;
}

http {
    sendfile on;
    tcp_nopush on;
    types_hash_max_size 2048;
    include /etc/nginx/mime.types;
    default_type application/octet-stream;
    ssl_protocols TLSv1 TLSv1.1 TLSv1.2 TLSv1.3; # Dropping SSLv3, ref: POODLE
    ssl_prefer_server_ciphers on;
    log_format ltsv 'time:$time_iso8601\t'
                    'remote_addr:$remote_addr\t'
                    'request_method:$request_method\t'
                    'request_length:$request_length\t'
                    'request_uri:$request_uri\t'
                    'https:$https\t'
                    'uri:$uri\t'
                    'query_string:$query_string\t'
                    'status:$status\t'
                    'bytes_sent:$bytes_sent\t'
                    'body_bytes_sent:$body_bytes_sent\t'
                    'referer:$http_referer\t'
                    'useragent:$http_user_agent\t'
                    'forwardedfor:$http_x_forwarded_for\t'
                    'request_time:$request_time\t'
                    'upstream_response_time:$upstream_response_time\t'
                    'x_userid:$upstream_http_x_userid';
    access_log /var/log/nginx/access.log ltsv;
    error_log /var/log/nginx/error.log;
    gzip on;
    include /etc/nginx/conf.d/*.conf;
    include /etc/nginx/sites-enabled/*;
}

nginxを再起動します

sudo systemctl restart nginx.service

この状態で再度ログ転送してみます

cd
./bench run --enable-ssl

New Relic Logs上のデータに x_userid が追加されました。

New Relic Logsのデータ

{
  "body_bytes_sent": "52857",
  "bytes_sent": "53124",
  "forwardedfor": "-",
  "hostname": "ip-10-200-1-171",
  "https": "on",
  "query_string": "-",
  "referer": "-",
  "remote_addr": "127.0.0.1",
  "request_length": "509",
  "request_method": "GET",
  "request_time": "0.032",
  "request_uri": "/api/user/chiyo890/icon",
  "service_name": "example.service",
  "status": "200",
  "timestamp": 1714472779000,
  "upstream_response_time": "0.032",
  "uri": "/api/user/chiyo890/icon",
  "useragent": "isucandar",
  "x_userid": "1017"
}

この状態だと下のようなNRQLで集計することができます

利用が多いuseridの集計

SELECT count(*) FROM Log
FACET x_userid LIMIT 10 SINCE 10 minutes ago

特定の userid のリクエスト履歴とレスポンスタイム

SELECT x_userid,request_uri,upstream_response_time
FROM Log WHERE x_userid = 1011 LIMIT 50 SINCE 1 day ago

lookupテーブルの活用

もう少し頑張って lookup テーブルを試してみます。今回は users テーブルの id,name カラムでcsvを作って lookup テーブルに追加してみます。

注意点

New Relicさんのブログにも記載がありますが、アップロードしたテーブル情報は難読化されないため、機密性の高い情報はアップロードしないほうが無難です。今回はテスト用データなのでユーザー名をアップロードしていますが、実際の環境で利用する場合はデータの機密性を充分に検討してから活用してください。

参考

Lookupテーブルでダッシュボードをリッチに＋α - Speaker Deck

CSVを取り込んだデータをNRQLで組み合わせる「LookupTable」 #初心者 - Qiita

MySQLで--secure-file-privというエラーが出たときのメモ - willwealth’s diary

MySQLでSELECTしたデータをCSVファイルに出力してみよう！【MAC環境】 | ポテパンスタイル

csv出力

sudo mysql isupipe

mysql> select id,name from users order by id limit 10;
+----+------------------+
| id | name             |
+----+------------------+
|  1 | test001          |
|  2 | ayamazaki0       |
|  3 | yoshidamiki0     |
|  4 | hidekimurakami0  |
|  5 | akemikobayashi0  |
|  6 | eishikawa0       |
|  7 | tomoya100        |
|  8 | kobayashiminoru0 |
|  9 | yamadakaori0     |
| 10 | tanakahanako0    |
+----+------------------+
10 rows in set (0.00 sec)

mysql> select @@secure_file_priv;
+-----------------------+
| @@secure_file_priv    |
+-----------------------+
| /var/lib/mysql-files/ |
+-----------------------+
1 row in set (0.00 sec)

mysql>  select id,name from users into outfile '/var/lib/mysql-files/users.csv' fields terminated by ',' enclosed by '"' escaped by '"' lines terminated by '\r\n';
Query OK, 1095 rows affected (0.00 sec)

/var/lib/mysql-files/users.csv の1行目に id,name のヘッダーをつけて lookup テーブルにアップロードします

この状態で再度ログ転送してみます

cd
./bench run --enable-ssl

アップロードしたlookupテーブルを結合して見える化することができます。

利用が多いユーザー名の集計

FROM Log JOIN (FROM lookup(users) select id,name)
ON numeric(x_userid) = id
SELECT count(*)
FACET name
since 20 minutes ago limit 10

ユーザー名で解析することができるようになりました。lookupテーブル便利ですね。

さいごに

ここまで読んでいただき、ありがとうございます。この記事が誰かの役に立ったら幸いです。

数年前 Fluentd + OpenSearch + Kibana が好きで見える化にハマっていた時期がありました。同じことがNew Relicでも容易にできます。試してみてください。

環境準備

やってみた

Fluentdのインストール

ログを構造化する

StatusCode別の集計

リクエスト多いURI TOP10

user_idをログに埋め込む

利用が多いuseridの集計

特定の userid のリクエスト履歴とレスポンスタイム

lookupテーブルの活用

利用が多いユーザー名の集計

さいごに

Visual Studio Codeの拡張機能でAmazon Q Developerを使ってみる

非推奨となったAMIを利用する方法（RHEL版）

WSL と VSCode を使った Python 開発環境構築

AWSクラウドでもっともセキュアなデータ消去方法 (暗号化消去)

【CI/CD for Amazon ECS】Blue/Greenデプロイの動きを触って理解する