データレイクハンズオンのログ生成部分が気になったので調査してみた

Fluentd では aws-fluent-plugin-kinesis というプラグインを導入することで、Data Firehose ストリームにログを直接配信することができます。
2024.05.06

コーヒーが好きな emi です。

データ分析系サービスの学習を進めているのですが、こちらの データレイクハンズオン が非常に良いコンテンツで、既に弊社ブログで紹介されております。

さて、このハンズオンは EC2 から出力されるログを Fluentd で収集・転送するところから始まるのですが、この EC2 からログを生成する部分は提供されている AMI から EC2 を立ち上げるだけでできてしまいます。

とても簡単なのですが、Data Firehose に流すための Fluentd の設定やログ生成部分はどうなっているのか気になってしまったので、EC2 インスタンスの中身を見ていきたいと思います。

EC2 の作成

Lab1 の手順に沿って構築した EC2 インスタンス「handson-minilake」にセッションマネージャーで接続します。


Lab1 より引用

ちなみにこの EC2 を起動すると Security Hub で EC2.18 Security groups should only allow unrestricted incoming traffic for authorized portsEC2.19 Security groups should not allow unrestricted access to ports with high risk が検出され通知されました。セキュリティグループがフルオープン(0.0.0.0/0 からの通信が許可されている)だったので、自身の端末からの通信のみ許可に変更しておきました。

root ユーザーに切り替え、ログが出力されていることを確認します。

sh-4.2$ sudo su -
Last login: Sun Apr 28 19:07:36 JST 2024 on pts/0
[root@ip-10-0-0-27 ~]# tail -f /root/es-demo/testapp.log
[2024-05-05 21:06:01+0900] WARNING prd-db02 uehara 1001 [This is Warning.]
[2024-05-05 21:06:01+0900] INFO prd-ap001 uchida 1001 [This is Information.]
[2024-05-05 21:06:01+0900] INFO prd-web001 imai 1001 [This is Information.]
[2024-05-05 21:06:01+0900] CRITICAL prd-ap001 uehara 1001 [This is Critical!!]
[2024-05-05 21:06:01+0900] INFO prd-db02 uehara 1001 [This is Information.]
[2024-05-05 21:06:01+0900] INFO prd-ap001 uehara 1001 [This is Information.]
[2024-05-05 21:06:01+0900] INFO prd-web001 imai 1001 [This is Information.]
[2024-05-05 21:06:01+0900] INFO prd-ap001 uchida 1001 [This is Information.]
[2024-05-05 21:06:01+0900] WARNING prd-web002 uehara 1001 [This is Warning.]
[2024-05-06 06:52:01+0900] INFO prd-batch01 uehara 1001 [This is Information.]
[2024-05-06 06:52:01+0900] INFO prd-db02 imai 1001 [This is Information.]
[2024-05-06 06:52:01+0900] WARNING prd-ap001 takeda 1001 [This is Warning.]
[2024-05-06 06:52:01+0900] INFO prd-batch01 ohmura 1001 [This is Information.]
[2024-05-06 06:52:01+0900] INFO prd-db02 imai 1001 [This is Information.]
[2024-05-06 06:52:01+0900] WARNING prd-web001 kimura 1001 [This is Warning.]
[2024-05-06 06:52:01+0900] INFO prd-batch01 nomura 1001 [This is Information.]
[2024-05-06 06:52:01+0900] CRITICAL prd-ap001 uehara 1001 [This is Critical!!]
[2024-05-06 06:52:01+0900] WARNING prd-batch01 uehara 1001 [This is Warning.]
[2024-05-06 06:52:01+0900] INFO prd-ap001 imai 1001 [This is Information.]
[2024-05-06 06:52:01+0900] WARNING prd-web002 imai 1001 [This is Warning.]
[2024-05-06 06:52:01+0900] INFO prd-web001 kimura 1001 [This is Information.]
^C
[root@ip-10-0-0-27 ~]#
tail コマンドに関する補足(クリックで展開)
  • tail:ファイルの最後の部分を表示しますが、どのように表示するかはオプションで指定できます。
  • -f:このオプションは "follow" の略で、ファイルに新しい内容が追加されると自動的にそれを出力画面に表示し続けることを意味します。ファイルが更新されるたびに最新のログ内容が続けて表示されます。
  • /root/es-demo/testapp.log:tail コマンドが操作するファイルのパスです。/root/es-demo/ ディレクトリにある testapp.log ファイルを指定しています。

本当のログみたいです。最後は Ctr + C で tail コマンドを止めました。

ログの生成元を突き止める

さて、ハンズオンによると

2分おきに10件前後のログを出力し、10分おきに300件のエラーログを出力し続ける EC2

だそうです。

/etc/crontab 内のファイルを確認して、システム全体で設定されている定期的なタスクがないかをチェックします。

sudo cat /etc/crontab

▼実行結果

[root@ip-10-0-0-27 ~]# sudo cat /etc/crontab
SHELL=/bin/bash
PATH=/sbin:/bin:/usr/sbin:/usr/bin
MAILTO=root
HOME=/

# For details see man 4 crontabs

# Example of job definition:
# .---------------- minute (0 - 59)
# |  .------------- hour (0 - 23)
# |  |  .---------- day of month (1 - 31)
# |  |  |  .------- month (1 - 12) OR jan,feb,mar,apr ...
# |  |  |  |  .---- day of week (0 - 6) (Sunday=0 or 7) OR sun,mon,tue,wed,thu,fri,sat
# |  |  |  |  |
# *  *  *  *  * user-name command to be executed

*/2  *  *  *  * root /root/es-demo/access_01.sh
*/10 *  *  *  * root /root/es-demo/access_err.sh

[root@ip-10-0-0-27 ~]#

18、19 行目の /root/es-demo/access_01.sh/root/es-demo/access_err.sh というスクリプトがそれぞれ 2 分おきと 10 分おきに実行されています。これらのスクリプトがログファイル /root/es-demo/testapp.log に対して定期的に書き込みを行っている可能性が非常に高いです。

これらのスクリプトが具体的に何を行っているのかを確認しましょう。

access_01.sh の中身

実行コマンド

sudo cat /root/es-demo/access_01.sh

▼実行結果

[root@ip-10-0-0-27 ~]# sudo cat /root/es-demo/access_01.sh
APPLOG=/root/es-demo/testapp.log
TIMESTAMP=`date '+%Y-%m-%d %H:%M:%S%z'`
HOST=prd-web001
USER=uehara
NUMBER=1001
TEXT="test text."

## Rundom Level
LOOP=`echo $(($(od -vAn -tu2 -N2 /dev/urandom)  % 20))`
echo $RNUM
echo $LOOP
i=1

while [ $i -le $LOOP ]
do
RNUM=`echo $(($(od -vAn -tu2 -N2 /dev/urandom)  % 100))`
if [ $RNUM -le 60 ] ;
then
  LEVEL=INFO
  TEXT="This is Information."
elif [ $RNUM -ge 61 ] && [ $RNUM -le 80 ];
  then
    LEVEL=WARNING
    TEXT="This is Warning."
elif [ $RNUM -ge 81 ] && [ $RNUM -le 90 ];
  then
    LEVEL=ERROR
    TEXT="This is ERROR."
elif [ $RNUM -ge 91 ] && [ $RNUM -le 99 ];
  then
    LEVEL=CRITICAL
    TEXT="This is Critical!!"
fi

echo $LEVEL

## Rundom Host
RNUM=`echo $(($(od -vAn -tu2 -N2 /dev/urandom)  % 100))`
if [ $RNUM -le 20 ] ;
then
  HOST=prd-ap001
elif [ $RNUM -ge 21 ] && [ $RNUM -le 30 ];
  then
    HOST=prd-db02
elif [ $RNUM -ge 31 ] && [ $RNUM -le 40 ];
  then
    HOST=prd-web002
elif [ $RNUM -ge 41 ] && [ $RNUM -le 50 ];
  then
    HOST=prd-batch01
elif [ $RNUM -ge 51 ] && [ $RNUM -le 60 ];
  then
    HOST=prd-db02
elif [ $RNUM -ge 61 ] && [ $RNUM -le 90 ];
  then
    HOST=prd-web001
elif [ $RNUM -ge 91 ] && [ $RNUM -le 99 ];
  then
    HOST=prd-batch01
fi

echo $HOST

## Rundom User
RNUM=`echo $(($(od -vAn -tu2 -N2 /dev/urandom)  % 100))`
if [ $RNUM -le 40 ] ;
then
  USER=uehara
elif [ $RNUM -ge 41 ] && [ $RNUM -le 45 ];
  then
    USER=ohmura
elif [ $RNUM -ge 46 ] && [ $RNUM -le 60 ];
  then
    USER=imai
elif [ $RNUM -ge 61 ] && [ $RNUM -le 62 ];
  then
    USER=sato
elif [ $RNUM -ge 63 ] && [ $RNUM -le 70 ];
  then
    USER=takeda
elif [ $RNUM -ge 71 ] && [ $RNUM -le 79 ];
  then
    USER=uchida
elif [ $RNUM -ge 80 ] && [ $RNUM -le 87 ];
  then
    USER=nomura
elif [ $RNUM -ge 88 ] && [ $RNUM -le 90 ];
  then
    USER=umeda
elif [ $RNUM -ge 91 ] && [ $RNUM -le 99 ];
  then
    USER=kimura
fi

echo $USER

# ADD Log Record
#echo "[`date '+%Y-%m-%d %H:%M:%S%z'`] critical prd-web020 suzuki 1001 xxxx" >> /home/ec2-user/es-demo1/td-demo/testapp.log
echo "[${TIMESTAMP}] ${LEVEL} ${HOST} ${USER} ${NUMBER} [${TEXT}]" >> ${APPLOG}
sleep 1
i=$(expr $i + 1)
done
[root@ip-10-0-0-27 ~]#

このスクリプトは「ログレベル」「ホスト」「ユーザー」の情報をランダムに生成しログファイルに書き込んでいます。

  • 基本変数の設定
    • APPLOG:ログファイルのパス
    • TIMESTAMP:現在のタイムスタンプ
    • HOST, USER, NUMBER, TEXT:ログに含める初期情報
  • ログレベルのランダム生成
    • 0~99 までのランダム数値を生成し、その値に基づいてログレベルを出力しています。
      • RNUM <= 60 の場合、INFO レベル(60% の確率)
      • 61 <= RNUM <= 80 の場合、WARNING レベル(20% の確率)
      • 81 <= RNUM <= 90 の場合、ERROR レベル(10% の確率)
      • 91 <= RNUM <= 99 の場合、CRITICAL レベル(9% の確率)
  • ホスト名のランダム生成
    • 同様にランダム数値を生成し、特定の範囲に応じて異なるホスト名を割り当てます。
  • ユーザーのランダム生成
    • 同様にランダム数値を生成し、ユーザー名を決定します。
  • ログの書き込み
    • 生成したデータをログファイルに書き込みます。LOOP 変数で指定された回数(1 から 20 回のランダムな回数)繰り返されます。
ランダム数値の生成部分に関する補足(クリックで展開)
  • od:octal dump で、ファイルの内容を指定された形式でダンプ
  • -v:重複した行を繰り返し表示
  • -An:詳細表示を無効
  • -tu2:符号なし 2 バイト整数で出力
  • -N2:2 バイトのデータを読み込む
  • /dev/urandom:Unix 系 OS で乱数を生成する疑似デバイス

コマンド od -vAn -tu2 -N2 /dev/urandom を使用すると、/dev/urandom のランダムなバイト列から 2 Byte(16 bit)のデータを読み出して、それを 0~65535 の符号なし整数として解釈します。その後、この値を 100 で割った余りを取っています(% 100)。これにより 0~99 までの範囲の値を生成しています。

access_err.sh の中身

実行コマンド

sudo cat /root/es-demo/access_err.sh

▼実行結果

[root@ip-10-0-0-27 ~]# sudo cat /root/es-demo/access_err.sh
APPLOG=/root/es-demo/testapp.log
TIMESTAMP=`date '+%Y-%m-%d %H:%M:%S%z'`
HOST=prd-db001
#USER=uehara
NUMBER=1003
TEXT="test text."

## Rundom Level
RNUM=`echo $(($(od -vAn -tu2 -N2 /dev/urandom)  % 100))`
#echo $RNUM
LEVEL=ERROR
TEXT="This is ERROR."

USER=takahashi

for i in `seq 0 300`
do
# ADD Log Record
#echo "[`date '+%Y-%m-%d %H:%M:%S%z'`] critical prd-web020 suzuki 1001 xxxx" >> /home/ec2-user/es-demo1/td-demo/testapp.log
  echo "[${TIMESTAMP}] ${LEVEL} ${HOST} ${USER} ${NUMBER} [${TEXT}]" >> ${APPLOG}
done
[root@ip-10-0-0-27 ~]#

このスクリプトは特定のエラーログを一度に 300 件ログファイルに書き込みます。

  • 基本変数の設定
    • APPLOG, TIMESTAMP, HOST, NUMBER, TEXTaccess_01.sh と同様にログファイルのパスと初期情報を設定。
  • 固定のエラーレベルの設定
    • LEVEL:常に ERROR
    • TEXT:常に "This is ERROR."
  • 固定のユーザーの設定
    • USERtakahashi
  • ログの書き込み
    • 上記情報を基に、ログファイルにエラーメッセージを 300 回書き込む

Fluentd の設定を確認

Fluentd とは、さまざまなシステムから出力されるログデータを収集、集約して、分析を行ったり、DB などにログデータを転送することができるデータ収集・管理ツールです。
収集したデータをフィルタリングや加工する機能を持ち、データを目的に応じて整形・変換することもできます。データ転送中にエラーが発生した場合でも、ログデータをバッファリングし、自動的に再送を試みることで、データの損失を防ぎます。

この EC2 には Fluentd が導入されています。Fluentd は通常、td-agent としてインストールされます。td-agent の存在を確認します。

実行コマンド

rpm -q td-agent

▼実行結果

[root@ip-10-0-0-27 ~]# rpm -q td-agent
td-agent-3.1.1-0.el6.x86_64
[root@ip-10-0-0-27 ~]#

存在しますね。td-agent の状態も確認します。

実行コマンド

sudo systemctl status td-agent

▼実行結果

[root@ip-10-0-0-27 ~]# sudo systemctl status td-agent
sudo: systemctl: command not found
[root@ip-10-0-0-27 ~]#

おっと。systemctl が使えません。OS のバージョンを見てみましょう。

実行コマンド

cat /etc/os-release

▼実行結果

[root@ip-10-0-0-27 ~]# cat /etc/os-release
NAME="Amazon Linux AMI"
VERSION="2017.09"
ID="amzn"
ID_LIKE="rhel fedora"
VERSION_ID="2017.09"
PRETTY_NAME="Amazon Linux AMI 2017.09"
ANSI_COLOR="0;33"
CPE_NAME="cpe:/o:amazon:linux:2017.09:ga"
HOME_URL="http://aws.amazon.com/amazon-linux-ami/"
You have new mail in /var/spool/mail/root
[root@ip-10-0-0-27 ~]#

OS のバージョンを見ると、NAME="Amazon Linux AMI"VERSION="2017.09" となっておりかなり古いですね。ひとまず動いているようなので一旦先に進みます。

Fluentd の設定ファイルである td-agent.conf を見てみましょう。
Fluentd の設定ファイル td-agent.conf は以下のようなセクションで構成されます。

  • <source>:データの入力元を定義します。ログファイルのパスや、syslog、HTTP などの入力プラグインを指定します
  • <match>:受け取ったデータに対してどのような処理を行うかを定義します。出力先となる S3 や Data Firehose、ファイルなどの出力プラグインを指定します。
  • <filter>:入力データを加工するためのフィルタリング処理を定義します。

では、vi エディタで開きます。

実行コマンド

sudo vi /etc/td-agent/td-agent.conf

▼実行結果(td-agent.conf の中身を確認したら :q! で保存せず閉じる)

/etc/td-agent/td-agent.conf

<source>
  @type tail
  path /root/es-demo/testapp.log
  pos_file /var/log/td-agent/testapp.log.pos
  format /^\[(?<timestamp>[^ ]* [^ ]*)\] (?<alarmlevel>[^ ]*) *? (?<host>[^ ]*) * (?<user>[^ ]*) * (?<number>.*) \[(?<text>.*)\]$/
  time_format %d/%b/%Y:%H:%M:%S %z
  types size:integer, status:integer, reqtime:float, runtime:float, time:time
  tag testappec2.log
</source>

<match testappec2.log>
  @type copy
  <store>
    @type kinesis_firehose
    delivery_stream_name minilake1
    flush_interval 1s
  </store>
</match>

確認すると、以下のことが分かります。

  • <source> セクション:Fluentd がどのログファイルを監視し、どのようなフォーマットでログを解析するか指定しています。
    • @type tail:ログファイルを継続的に監視し、新しいログが追加されたときに読み込むための設定。
    • path:監視するログファイルのパス。/root/es-demo/testapp.log が指定されています。
    • pos_file:Fluentd がどこまでログファイルを読み込んだかを記録する位置ファイルのパス。この設定をすると Fluentd が再起動した後も正しい位置からログ読み込みを再開できます。
    • format:ログのフォーマットを正規表現で指定。ログから特定の情報を抽出して、フィールドとして扱うことができます。
    • time_format:ログのタイムスタンプのフォーマットを指定。
    • types:抽出したフィールドのデータ型を指定。
    • tag:このログソースに割り当てられるタグ。このタグを使って、後続の処理(フィルターやマッチング)を識別します。
  • <match> セクション:特定のタグにマッチしたログデータにどのような処理を施すかを定義しています。
    • @type copy:受け取ったデータを複数の出力先(<store>)にコピーします。ここでは 1 つの出力先が指定されていますが、必要に応じて複数の <store> を追加できます。
    • <store>
    • @type kinesis_firehose:出力タイプとして Amazon Data Firehose(旧 Amazon Kinesis Data Firehose)を使用します。
    • delivery_stream_name:Data Firehose のデリバリーストリーム名を指定します。Lab4 で作成する Firehose ストリーム名である minilake1 が指定されています。
    • flush_interval:データを Data Firehose に送信する間隔を指定します。ここでは 1 秒ごとに設定されています。

/root/es-demo/testapp.log から読み取ったログデータは、指定されたフォーマットに変換され、変換されたデータはタグ testappec2.log を通じて Data Firehose に送信され、1 秒ごとにフラッシュ(送信)されることが分かりました。

aws-fluent-plugin-kinesis プラグインの確認

Fluentd から Data Firehose にログを送付するには aws-fluent-plugin-kinesis プラグインが導入されている必要があります。

上記 GitHub で紹介されているインストール方法は Ruby 環境が前提になっていますが、Amazon Linux 系の OS を使用している場合は以下 Fluentd の公式ドキュメントに記載されているように td-agent を使用するのが便利なようです。

さて、本ハンズオンで作成して EC2 インスタンスに aws-fluent-plugin-kinesis プラグインが導入されていることを確認します。

[root@ip-10-0-0-27 ~]# td-agent-gem list | grep fluent-plugin-kinesis
fluent-plugin-kinesis (2.1.0)
[root@ip-10-0-0-27 ~]#

ありますね。いろいろ確認できて満足しました。

終わりに

EC2 から出力されたログを Fluentd で Data Firehose に送信する前の部分を調査してみました。Fluentd やプラグインの使い方が分かってよかったです。
ハンズオンとして提供されている EC2 の OS が古かったり、セキュリティグループがフルオープンだったりしますので、安全のため検証後は早めに削除しておくと安心です。

参考