PHPとFluentdで実現するリアルタイムログ分析

PHPerKaigi2024の登壇資料です。
https://fortee.jp/phperkaigi-2024/proposal/c27dee07-1f76-481f-89fa-3d7e7604bdfd

Transcript

1. PHPとFluentdで実現する リアルタイムログ分析 pixiv Inc. 当田 昇(@picopico_dev) 2024.03.09
2. 2 会社 ピクシブ株式会社 経歴 2023年4⽉ 新卒⼊社 職種 pixiv事業本部ウェブチーム 兼 インフラ部SREチーム 当⽥ 昇 @picopico_dev
3. 1. リアルタイムログ分析とは 2. Fluentdの概要 3. Fluentdを用いたPHPアプリケーションのログ分析手法
4. 1. リアルタイムログ分析とは 2. Fluentdの概要 3. Fluentdを用いたPHPアプリケーションのログ分析手法
5. ログ分析って何？
6. 6 Databases Syslog Application logs Access logs Error logs
7. 7 Databases Syslog Application logs Access logs Error logs Elastic Search Big Query MySQL Amazon S3
8. ログを集めてどうするの？ →データ駆動で意思決定を行う 8
9. データ駆動で意思決定を行う 9 • 異常検知 • ユーザー行動分析 • デバッグ • 内部監査
10. 大量のログをリアルタイムに 効率良く捌けるミドルウェアが必要 10
11. ログの特徴
12. ログの特徴 12 1. 複数のサーバーで発生する 2. データ形式が多種多様 3. リアルタイムで大量に書き込まれる
13. ログの特徴 13 1. 複数のサーバーで発生する 2. データ形式が多種多様 3. リアルタイムで大量に書き込まれる
14. 14 User Gateway AP003 AP002 AP001 DB001 DB002
15. 15 User Gateway AP003 AP002 AP001 DB001 DB002
16. ログの特徴 16 1. 複数のサーバーで発生する 2. データ形式が多種多様 3. リアルタイムで大量に書き込まれる
17. (例)Nginxのアクセスログ 192.168.1.1 - - [08/Mar/2023:12:00:00 +0000] "GET /index.html HTTP/1.1" 200 612 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36"
18. (例)Nginxのアクセスログ 192.168.1.1 - - [08/Mar/2023:12:00:00 +0000] "GET /index.html HTTP/1.1" 200 612 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36" →構造化されていない、独自のシンプルな形式が多い
19. ログの特徴 19 1. 複数のサーバーで発生する 2. データ形式が多種多様 3. リアルタイムで大量に書き込まれる
20. 20 想定シナリオ: あるウェブアプリケーションが毎日平均して 100万回のアクセスを受けるとします。各アクセスは、ユー ザー認証、ページビュー、 APIリクエストなど複数のログエントリを生成すると仮定します。 ログ量の推計 1アクセスあたりのログエントリ数 : 5件（認証、ページビュー、 APIリクエストx3） 1日あたりの総ログエントリ数 : 100万アクセス × 5 = 500万件 1ログエントリの平均サイズ : 500バイト（日時、セッション ID、アクション詳細などを含む） これらの値を元に1日あたりのログデータの総量を計算すると、
21. 21 想定シナリオ: あるウェブアプリケーションが毎日平均して 100万回のアクセスを受けるとします。各アクセスは、ユー ザー認証、ページビュー、 APIリクエストなど複数のログエントリを生成すると仮定します。 ログ量の推計 1アクセスあたりのログエントリ数 : 5件（認証、ページビュー、 APIリクエストx3） 1日あたりの総ログエントリ数 : 100万アクセス × 5 = 500万件 1ログエントリの平均サイズ : 500バイト（日時、セッション ID、アクション詳細などを含む） これらの値を元に1日あたりのログデータの総量を計算すると、 1日あたりのログデータ量: 500万件 × 500バイト = 2,500,000,000バイト（約2.33GB）
22. ログの例
23. [08-Mar-2023 12:00:00 UTC] PHP Warning: Division by zero in /path/to/your/script.php on line 10 [08-Mar-2023 12:00:02 UTC] PHP Fatal error: Uncaught Error: Call to undefined function testFunction() in /path/to/your/script.php:15 PHPのエラーログ
24. [08-Mar-2023 12:00:00 UTC] PHP Warning: Division by zero in /path/to/your/script.php on line 10 [08-Mar-2023 12:00:02 UTC] PHP Fatal error: Uncaught Error: Call to undefined function testFunction() in /path/to/your/script.php:15 PHPのエラーログ タイムスタンプ
25. [08-Mar-2023 12:00:00 UTC] PHP Warning: Division by zero in /path/to/your/script.php on line 10 [08-Mar-2023 12:00:02 UTC] PHP Fatal error: Uncaught Error: Call to undefined function testFunction() in /path/to/your/script.php:15 PHPのエラーログ エラーの種類
26. [08-Mar-2023 12:00:00 UTC] PHP Warning: Division by zero in /path/to/your/script.php on line 10 [08-Mar-2023 12:00:02 UTC] PHP Fatal error: Uncaught Error: Call to undefined function testFunction() in /path/to/your/script.php:15 PHPのエラーログ エラーの詳細、発生場所
27. Nginxのアクセスログ 192.168.1.1 - - [08/Mar/2023:12:00:00 +0000] "GET /index.html HTTP/1.1" 200 612 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36"
28. Nginxのアクセスログ 192.168.1.1 - - [08/Mar/2023:12:00:00 +0000] "GET /index.html HTTP/1.1" 200 612 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36" IPアドレス
29. Nginxのアクセスログ 192.168.1.1 - - [08/Mar/2023:12:00:00 +0000] "GET /index.html HTTP/1.1" 200 612 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36" リモートユーザー名・ユーザーID
30. Nginxのアクセスログ 192.168.1.1 - - [08/Mar/2023:12:00:00 +0000] "GET /index.html HTTP/1.1" 200 612 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36" タイムスタンプ
31. Nginxのアクセスログ 192.168.1.1 - - [08/Mar/2023:12:00:00 +0000] "GET /index.html HTTP/1.1" 200 612 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36" リクエスト
32. Nginxのアクセスログ 192.168.1.1 - - [08/Mar/2023:12:00:00 +0000] "GET /index.html HTTP/1.1" 200 612 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36" HTTPステータスコード・バイト数
33. Nginxのアクセスログ 192.168.1.1 - - [08/Mar/2023:12:00:00 +0000] "GET /index.html HTTP/1.1" 200 612 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36" リファラ
34. Nginxのアクセスログ 192.168.1.1 - - [08/Mar/2023:12:00:00 +0000] "GET /index.html HTTP/1.1" 200 612 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36" ユーザーエージェント
35. MySQLのログ 2023-03-08T12:00:00.000000Z 0 [Note] InnoDB: Buffer pool(s) load completed at 230308 8:00:00 2023-03-08T12:00:00.000000Z 0 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode. 2023-03-08T12:00:00.000000Z 0 [ERROR] Cannot open table test/users from the internal data dictionary of InnoDB though the .frm file for the table exists.
36. MySQLのログ 2023-03-08T12:00:00.000000Z 0 [Note] InnoDB: Buffer pool(s) load completed at 230308 8:00:00 2023-03-08T12:00:00.000000Z 0 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode. 2023-03-08T12:00:00.000000Z 0 [ERROR] Cannot open table test/users from the internal data dictionary of InnoDB though the .frm file for the table exists. タイムスタンプ
37. MySQLのログ 2023-03-08T12:00:00.000000Z 0 [Note] InnoDB: Buffer pool(s) load completed at 230308 8:00:00 2023-03-08T12:00:00.000000Z 0 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode. 2023-03-08T12:00:00.000000Z 0 [ERROR] Cannot open table test/users from the internal data dictionary of InnoDB though the .frm file for the table exists. プロセスID
38. MySQLのログ 2023-03-08T12:00:00.000000Z 0 [Note] InnoDB: Buffer pool(s) load completed at 230308 8:00:00 2023-03-08T12:00:00.000000Z 0 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode. 2023-03-08T12:00:00.000000Z 0 [ERROR] Cannot open table test/users from the internal data dictionary of InnoDB though the .frm file for the table exists. ログレベル
39. MySQLのログ 2023-03-08T12:00:00.000000Z 0 [Note] InnoDB: Buffer pool(s) load completed at 230308 8:00:00 2023-03-08T12:00:00.000000Z 0 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode. 2023-03-08T12:00:00.000000Z 0 [ERROR] Cannot open table test/users from the internal data dictionary of InnoDB though the .frm file for the table exists. ログ内容
40. システムログ(syslog) Mar 8 12:00:00 myhost systemd[1]: Started Session 1234 of user root. Mar 8 12:05:00 myhost sshd[23456]: Accepted publickey for user1 from 192.168.1.100 port 22 ssh2 Mar 8 12:10:00 myhost CRON[23457]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1) Mar 8 12:15:00 myhost kernel: [123456.789012] Firewall: *TCP_IN Blocked* IN=eth0 OUT= MAC=01:23:45:67:89:ab:cd:ef:gh:ij:kl:mn SRC=10.1.2.3 DST=192.168.1.100 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=12345 DF PROTO=TCP SPT=12345 DPT=80 WINDOW=65535 RES=0x00 SYN URGP=0
41. システムログ(syslog) Mar 8 12:00:00 myhost systemd[1]: Started Session 1234 of user root. Mar 8 12:05:00 myhost sshd[23456]: Accepted publickey for user1 from 192.168.1.100 port 22 ssh2 Mar 8 12:10:00 myhost CRON[23457]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1) Mar 8 12:15:00 myhost kernel: [123456.789012] Firewall: *TCP_IN Blocked* IN=eth0 OUT= MAC=01:23:45:67:89:ab:cd:ef:gh:ij:kl:mn SRC=10.1.2.3 DST=192.168.1.100 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=12345 DF PROTO=TCP SPT=12345 DPT=80 WINDOW=65535 RES=0x00 SYN URGP=0 タイムスタンプ
42. システムログ(syslog) Mar 8 12:00:00 myhost systemd[1]: Started Session 1234 of user root. Mar 8 12:05:00 myhost sshd[23456]: Accepted publickey for user1 from 192.168.1.100 port 22 ssh2 Mar 8 12:10:00 myhost CRON[23457]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1) Mar 8 12:15:00 myhost kernel: [123456.789012] Firewall: *TCP_IN Blocked* IN=eth0 OUT= MAC=01:23:45:67:89:ab:cd:ef:gh:ij:kl:mn SRC=10.1.2.3 DST=192.168.1.100 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=12345 DF PROTO=TCP SPT=12345 DPT=80 WINDOW=65535 RES=0x00 SYN URGP=0 ホスト名
43. システムログ(syslog) Mar 8 12:00:00 myhost systemd[1]: Started Session 1234 of user root. Mar 8 12:05:00 myhost sshd[23456]: Accepted publickey for user1 from 192.168.1.100 port 22 ssh2 Mar 8 12:10:00 myhost CRON[23457]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1) Mar 8 12:15:00 myhost kernel: [123456.789012] Firewall: *TCP_IN Blocked* IN=eth0 OUT= MAC=01:23:45:67:89:ab:cd:ef:gh:ij:kl:mn SRC=10.1.2.3 DST=192.168.1.100 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=12345 DF PROTO=TCP SPT=12345 DPT=80 WINDOW=65535 RES=0x00 SYN URGP=0 プロセス名とプロセスID
44. システムログ(syslog) Mar 8 12:00:00 myhost systemd[1]: Started Session 1234 of user root. Mar 8 12:05:00 myhost sshd[23456]: Accepted publickey for user1 from 192.168.1.100 port 22 ssh2 Mar 8 12:10:00 myhost CRON[23457]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1) Mar 8 12:15:00 myhost kernel: [123456.789012] Firewall: *TCP_IN Blocked* IN=eth0 OUT= MAC=01:23:45:67:89:ab:cd:ef:gh:ij:kl:mn SRC=10.1.2.3 DST=192.168.1.100 LEN=60 TOS=0x00 PREC=0x00 TTL=64 ID=12345 DF PROTO=TCP SPT=12345 DPT=80 WINDOW=65535 RES=0x00 SYN URGP=0 ログ内容
45. ログの処理
46. バッチ処理とストリーム処理の違 い
47. バッチ処理の例 total 40 -rw-r--r-- 1 root root 1024 Mar 5 00:00 app.log-20230304 -rw-r--r-- 1 root root 20480 Mar 6 00:00 app.log-20230305 -rw-r--r-- 1 root root 10240 Mar 7 00:00 app.log-20230306 -rw-r--r-- 1 root root 5120 Mar 8 00:00 app.log-20230307 -rw-r--r-- 1 root root 123 Mar 8 12:00 app.log
48. バッチ処理の例 total 40 -rw-r--r-- 1 root root 1024 Mar 5 00:00 app.log-20230304 -rw-r--r-- 1 root root 20480 Mar 6 00:00 app.log-20230305 -rw-r--r-- 1 root root 10240 Mar 7 00:00 app.log-20230306 -rw-r--r-- 1 root root 5120 Mar 8 00:00 app.log-20230307 -rw-r--r-- 1 root root 123 Mar 8 12:00 app.log 1日ごとに処理する
49. バッチ処理の例 total 40 -rw-r--r-- 1 root root 1024 Mar 5 00:00 app.log-20230304 -rw-r--r-- 1 root root 20480 Mar 6 00:00 app.log-20230305 -rw-r--r-- 1 root root 10240 Mar 7 00:00 app.log-20230306 -rw-r--r-- 1 root root 5120 Mar 8 00:00 app.log-20230307 -rw-r--r-- 1 root root 123 Mar 8 12:00 app.log 1日ごとに処理する
50. バッチ処理の例 total 40 -rw-r--r-- 1 root root 1024 Mar 5 00:00 app.log-20230304 -rw-r--r-- 1 root root 20480 Mar 6 00:00 app.log-20230305 -rw-r--r-- 1 root root 10240 Mar 7 00:00 app.log-20230306 -rw-r--r-- 1 root root 5120 Mar 8 00:00 app.log-20230307 -rw-r--r-- 1 root root 123 Mar 8 12:00 app.log 1日ごとに処理する
51. バッチ処理の例 total 40 -rw-r--r-- 1 root root 1024 Mar 5 00:00 app.log-20230304 -rw-r--r-- 1 root root 20480 Mar 6 00:00 app.log-20230305 -rw-r--r-- 1 root root 10240 Mar 7 00:00 app.log-20230306 -rw-r--r-- 1 root root 5120 Mar 8 00:00 app.log-20230307 -rw-r--r-- 1 root root 123 Mar 8 12:00 app.log 1日ごとに処理する
52. バッチ処理の特徴 52 [Pros] 大量のデータを一括で処理するため、効率的に処理できる [Cons] リアルタイムで処理できず、1回の実行に時間がかかる
53. ストリーム処理の例 (app.log) [2023-03-08 12:00:01 UTC] PHP Warning: include(/path/to/file/mi [2023-03-08 12:01:02 UTC] PHP Notice: Undefined variable: usern [2023-03-08 12:02:03 UTC] PHP Fatal error: Uncaught Error: Call Stack trace: #0 {main} thrown in /path/to/your/script.php on line 70
54. ストリーム処理の例 (app.log) [2023-03-08 12:00:01 UTC] PHP Warning: include(/path/to/file/mi
55. ストリーム処理の例 (app.log) [2023-03-08 12:00:01 UTC] PHP Warning: include(/path/to/file/mi [2023-03-08 12:01:02 UTC] PHP Notice: Undefined variable: usern
56. ストリーム処理の例 (app.log) [2023-03-08 12:00:01 UTC] PHP Warning: include(/path/to/file/mi [2023-03-08 12:01:02 UTC] PHP Notice: Undefined variable: usern [2023-03-08 12:02:03 UTC] PHP Fatal error: Uncaught Error: Call Stack trace: #0 {main} thrown in /path/to/your/script.php on line 70
57. ストリーム処理の特徴 57 [Pros] リアルタイムに分析できる [Cons] リソース要求が高く、処理ロジックが複雑である
58. 1. リアルタイムログ分析とは 2. Fluentdの概要 3. Fluentdを用いたPHPアプリケーションのログ分析手法
59. Fluentdとは？
60. Fluentdの特徴 60 • Unified Logging with JSON • Pluggable Architecture • Minimum Resources Required • Built-in Reliability
61. Fluentdの特徴 61 • Unified Logging with JSON • Pluggable Architecture • Minimum Resources Required • Built-in Reliability
62. 62 イベント [08-Mar-2023 12:00:00 UTC] PHP Warning: Division by zero in /path/to/your/script.php on line 10 [“app.log”, 2023-03-08T12:00:00Z, {"level": "WARNING","message": "Division by zero", …}] Input
63. 63 イベント [08-Mar-2023 12:00:00 UTC] PHP Warning: Division by zero in /path/to/your/script.php on line 10 [“app.log”, 2023-03-08T12:00:00Z, {"level": "WARNING","message": "Division by zero", …}] Inputプラグインがログからイベ ントを生成する Input
64. Fluentdの特徴 64 • Unified Logging with JSON • Pluggable Architecture • Minimum Resources Required • Built-in Reliability
65. Pluggable Architecture 65 • Rubyのプラグインで入力・出力が自在 • 500個以上のプラグインが公開されている
67. Fluentdの特徴 67 • Unified Logging with JSON • Pluggable Architecture • Minimum Resources Required • Built-in Reliability
68. Minimum Resources Required 68 • 処理部分がC言語で実装されており高速 • 30-40MBのメモリで13000events/秒・コアを処理できる
69. Fluentdの特徴 69 • Unified Logging with JSON • Pluggable Architecture • Minimum Resources Required • Built-in Reliability
70. Built-in Reliability 70 • File bufferに対応し、ログ欠損を防止 • 転送に失敗してもリトライ機構が備わっている
71. ログのフロー
72. 72 /var/log/app.log AP
73. 73 /var/log/app.log AP Fluentdをエージェントとしてイン ストールする
74. 74 /var/log/app.log input AP output
75. 75 DB AP Aggregator Gateway
76. Fluentdの設定
77. fluent.conf <source> @type forward </source> <filter app.**> @type grep <regexp> key level pattern /^ERROR$/ </regexp> </filter> <match app.**> @type file path /var/log/fluentd/error_logs </match>
78. fluent.conf <source> @type forward </source> <filter app.**> @type grep <regexp> key level pattern /^ERROR$/ </regexp> </filter> <match app.**> @type file path /var/log/fluentd/error_logs </match>
79. fluent.conf <source> @type forward </source> <filter app.**> @type grep <regexp> key level pattern /^ERROR$/ </regexp> </filter> <match app.**> @type file path /var/log/fluentd/error_logs </match>
80. fluent.conf <source> @type forward </source> <filter app.**> @type grep <regexp> key level pattern /^ERROR$/ </regexp> </filter> <match app.**> @type file path /var/log/fluentd/error_logs </match>
81. ディレクティブ 81 • <source>: 入力 • <match>: 出力 • <parse>: ログの構造化 • <filter>: ログの選択・加工 • <buffer>: バッファリング • …
82. 1. リアルタイムログ分析とは 2. Fluentdの概要 3. Fluentdを用いたPHPアプリケーションのログ分析手法
83. PHPとFluentdの設計例
84. 84 AP003 AP002 AP001 Aggregator
85. 85 AP003 AP002 AP001 Aggregator
86. PHP側のログ出力設定 (php.ini) log_errors = On error_log = /var/log/app.log
87. 87 AP003 AP002 AP001 Aggregator
88. Fluentdの設定(AP側) <source> @type tail path /var/log/app.log pos_file /var/log/app.log.pos tag php.error <parse> @type regexp expression /^(?<time>[^ ]* [^ ]*) (?<type>[^:]*): (?<message time_format %d-%b-%Y %H:%M:%S types time:time,type:string,message:string,file:string,line: </parse> </source>
89. 89 AP003 AP002 AP001 Aggregator
90. Fluentdの設定(AP側) <match php.error> @type forward <server> host aggregator port 24224 </server> </match>
91. Fluentdの設定(Aggregator側) <source> @type forward port 24224 </source>
92. 92 AP003 AP002 AP001 Aggregator
93. Fluentdの設定(Aggregator側) <match php.error> @type mysql_bulk host mysql database db username root password root column_names time,type,message,file,line table php_errors <buffer> flush_interval 10s </buffer> </match>
94. 94 AP003 AP002 AP001 Aggregator
95. なぜログ集約サーバーが必要なのか 95 • 責務の分離 • リソースの効率化 • バッファリング
96. NEXT STEP
97. NEXT STEP 97 • 公式ドキュメント(https://docs.fluentd.org/) • Fluentd実践入門 ── 統合ログ基盤のためのデータ収集ツー ル
98. おわり