CloudWatch Logsエージェントを検証してみた

先日リリースされたCloudWatch Logs、監視ツールを開発していた者としては注目せざるを得ません。
特に、ログ監視エージェントにはこだわりがあるので、CloudWatch Logsエージェントの細かな動作に興味をもちました。
そこで、今回はCloudWatch Logsエージェントを5つの観点から検証してみました。

はじめに

ログ監視エージェントにとって重要な5つのポイントを考えてみました。

  • メッセージラッシュ
  • ロングメッセージ
  • ログローテーション
  • 一時的な通信断
  • エージェント停止

メッセージラッシュ

障害発生時等に短時間に大量のメッセージが発生することをメッセージラッシュと呼びます。
このメッセージラッシュが発生した際にも、安定して動作してメッセージをロストせずに監視できることは、ログ監視エージェントにとって重要なポイントです。
そこで、メッセージラッシュを意図的に発生させ、ロストせずに監視できることを確認します。

まず、下記コマンドにて、CloudWatch Logsの監視対象ログファイルに10000件のメッセージをno sleepで全力で出力します。

for i in `seq 1 1 10000`; do echo "CloudWatch Logs Test No.$i" >> /var/log/awslogs_testing_rush.log ; done

約1秒で10000行出力しきりました。

マネジメントコンソールから確認してみます。
rush
10000件目のメッセージまで記録されているようです。

では、コマンドラインから、記録されたメッセージの数を見てみます。

# /var/awslogs/bin/aws logs get-log-events --log-group-name /var/log/awslogs_testing_rush.log --log-stream-name i-1427b938 | grep timestamp | wc -l
10000

1件もロストすることなく、ちょうど10000件記録されていることを確認しました。

ちなみに、もし検証を手元で試される場合は、下記の点にご注意ください。

  • get-log-eventsで取得できる最大ログイベント数は10000であるため、それより多くのメッセージを出力した場合は別の確認方法が必要になります。
  • 今回は、LogStreamを削除してログファイル作成直後に10000件メッセージを出力したため、件数のカウントだけでロストチェックしていますが、他のメッセージが既に書き込まれた状態から検証を始める場合は別の確認方法が必要になります。

ロングメッセージ

ログファイルを出力するアプリケーションによっては、1行のログメッセージが非常に長大になる場合があります。
このようなケースでも、送信可能な長さを超えるメッセージは切り詰めて送信・記録するなど、何らかの方法で完全にロストすることなく監視できることは、ログ監視エージェントにとって重要なポイントです。
そこで、非常に長いログメッセージを出力してみて、正常に監視できることを確認します。

まず、CloudWatch Logsの監視対象ログファイルに1行で1000000 byteのメッセージを出力するスクリプトを用意します。

#!/usr/bin/ruby
str = "a"*1000000
open("/var/log/awslogs_testing.log", "a") {|f| f.write str}

早速実行します。

ruby create_long_message.rb

マネジメントコンソールで確認してみます。
truncated

[TRUNCATED MESSAGE] 1000000 bytes are truncated.

truncate された旨がログ出力されています。

try and error して調べた感じだと、32742 byte 以下では truncate されなかったので、32743 byte を閾値に truncate されているようです。
threshold_32743

/var/log/awslogs.logには下記のように出力されていました。
2014-07-15 09:41:13,704 - cwlogs.push - WARNING - Thread-397 - Truncate event: {'source_id': 'cd83dfb8f052eedd9816109b0e809ff7', 'timestamp': None,
 'start_position': 392252L, 'end_position': 424995L}, reason: single event exceeds 32KB limit.

以上の通り、32742 byte 以下のメッセージは監視でき、さらに 32743 byte 以上のメッセージについても truncate された旨を把握できることを確認しました。

ログローテーション

実運用しているサーバでは、ログファイルを定期的にローテーションするように設定するのが一般的です。
このように定期的にローテーションされるログファイルについても継続して監視できることは、ログ監視エージェントにとって重要なポイントです。
そこで、logrotate によりローテーションしてみて、追従して監視できることを確認します。

下記のファイルを作成し、/etc/logrotate.d/awslogs_testing に配置します。

/var/log/awslogs_testing.log {
    missingok
    rotate 4
    create
    size 1
}

以下のコマンドでローテートさせます。

logrotate /etc/logrotate.d/awslogs_testing

ログ出力します。

echo "log rotated" >> /var/log/awslogs_testing.log

マネジメントコンソールから、ローテート後のログメッセージも記録されていることを確認できました。
rotated

一時的な通信断

サーバを長期的に運用するにあたり、何らかの問題で一時的な通信断が発生する場合もあるかと思います。
このような場合でも、メッセージをロストせず、通信復旧時に再送することにより、継続して監視できることは、ログ監視エージェントにとって重要なポイントです。
そこで、セキュリティグループの設定により一時的に通信断状態とし、復旧後に通信断の期間のログも監視できることを確認します。

セキュリティグループの設定でOutboundのHTTPSをブロックします。
今回は簡単に設定するため、All traffic の許可ルールを削除しちゃいます。
no_outbound

この状態でログ出力します。

echo "cannot connect" >> /var/log/awslogs_testing.log

マネジメントコンソール側で確認すると、ログが記録されません。

次に、セキュリティグループの設定でOutboundのAll traffic の許可ルールを復活させます。

マネジメントコンソールから、さきほどのログが記録されたことが確認できました。
cannot_connect

エージェント停止

アプリケーションがログを出力するとき、当然ログ監視エージェントの動作状況を気にしてはくれません。
ログ監視エージェントが起動する前にログが出力されたり、何らかの事情でログ監視エージェントが停止している間にログが出力されたりすることは、よくあることです。
そもそも、ログ監視エージェントを導入する前に、既に出力されていたログファイルも存在するかと思います。
このような場合でも、エージェント停止中に出力されたログをロストせず監視できることは、ログ監視エージェントにとって重要なポイントです。

まず、awslogsサービスを停止します。

service awslogs stop

この状態でログ出力します。

echo "stopped" >> /var/log/awslogs_testing_stop.log

しばらくしてから、awslogsサービスを再開します。

service awslogs start

マネジメントコンソールから、さきほどのログが記録されたことが確認できました。
stopped

その他

  • CloudWatch Logsエージェントのログは/var/log/awslogs.logに出力される。
  • /var/log/awslogs.logはdailyでrotateされる。
  • 日本語メッセージもUTF-8なら大丈夫。japanese
  • ログファイル名が日本語なのは無理っぽい。

おわりに

今回はCloudWatch Logsエージェントを検証してみました。
今後もいろいろ弄って遊んでみたいと思います。

2014
07/16
CATEGORY
AWS
CloudWatch
コメントを書く

コメントを残す