LambdaでS3上に出力されたログをCloudWatch Logsに取り込んで監視する

この記事はAWS Lambda Advent Calendar 2014の12/8のエントリです。
昨日7日目のエントリはmaroon1stさんの「今後のLambdaの機能拡張に対する要望を挙げてみた – AWS Lambda Advent Calendar 2014：7日目」でした。
今日8日目は、LambdaでS3上に出力されたログをCloudWatch Logsに取り込んで監視してみます。

CloudWatch Logsはログの蓄積や監視を実現するためのサービスとして、2014年7月にリリースされました。
現時点では、Linuxでは任意のログファイルの監視に、Windowsでは任意のログファイルに加えてWindows Eventlog・Event Tracing for Windowsの監視にも対応し、CloudWatch Logsは既にEC2インスタンス内部のログの大部分に対応していると言えるでしょう。
また、2014年11月にはCloudTrailで記録したAPI callのログ(Trail)をCloudWatch Logsに投入することができるようになりました。

でもAWSでは他にもログがあります。AWSのサービス自体が出力するログです。
ELBやS3、CloudFrontなど、AWSのサービス自体が出力するログの多くはS3上に出力されます。
今回はこれらのS3上に出力されるログをターゲットに、Lambdaを使ってCloudWatch Logsに取り込んで監視する方法を考えてみます。

lambda

Lambdaコード

何はともあれ、まずはLambdaコードです。

var aws = require('aws-sdk');
var s3 = new aws.S3({apiVersion: '2006-03-01'});
var cloudwatchlogs = new aws.CloudWatchLogs({region: 'us-east-1'});

exports.handler = function(event, context) {
   var bucket = event.Records[0].s3.bucket.name;
   var key = event.Records[0].s3.object.key;
   s3.getObject({Bucket:bucket, Key:key},
      function(err,data) {
        if (err) {
            console.log('error getting object ' + key + ' from bucket ' + bucket + 
               '. Make sure they exist and your bucket is in the same region as this function.');
            context.done('error','error getting file'+err);
        }
        else {
            var contentEncoding = data.ContentEncoding;
            
            var logEvents = [];

            var contentBody = data.Body.toString(contentEncoding);
            contentBody.split('\n').forEach(function (line) {
                var logEvent = {
                    message: line,
                    timestamp: new Date().getTime()
                }
                if (line.length > 0){ 
                    logEvents.push(logEvent);
                }
            });
            
            var param = {
                logEvents: logEvents,
                logGroupName: 'hoge-group',
                logStreamName: 'fuga-stream',
                sequenceToken: null
            };
            
            var request = cloudwatchlogs.putLogEvents(param, function(err, data) {
                if (err) {
                    if (err['code'] == 'InvalidSequenceTokenException'){
                        var nextSequenceToken = err['message'].match(/[0-9]+/).pop();
                        console.log ('nextSequenceToken = '+nextSequenceToken);
                        param['sequenceToken'] = nextSequenceToken;
                        var retryRequest = cloudwatchlogs.putLogEvents(param, function(err, data) {
                            if (err) {
                                context.done("retryRequest error", err);
                            } else {
                                context.done(null,'put retry succeeded');
                            }
                        });
                    } else {
                        context.done("unknown error", err);
                    }
                } else {
                    context.done(null,'put succeeded');
                }
            });
        }
      }
   );
};

解説

簡単に処理を解説すると、下記のような感じ。

  1. S3に出力されたファイルの本文を1行ずつに分解する
  2. ファイルの1行とタイムスタンプをCloudWatch LogsのLog Eventとしてまとめる
  3. 対象ファイルのLog Eventを全部まとめて1つのBatchをつくってCloudWatch Logsにアップロードする
    • このアップロードの時点では次のsequenceTokenを知らないので、とりあえずsequenceTokenにnullを入れて1回トライして、エラーからsequenceTokenを取得してリトライする

このような処理の都合上、改行区切りのログにのみ対応しています。
ELBやS3、CloudFrontのログは皆改行区切りなので大丈夫ですね。
また、Log EventにはLog Eventをつくるときのタイムスタンプを使っていて、ログの行に含まれるタイムスタンプをパースして使っているわけではありません。
このため、Log Eventのタイムスタンプにログの正確な日時を挿入したい場合は、ログに合わせてパースするなどの工夫が必要になります。

動作確認

試しに、S3のアクセスログを出力するように設定したS3バケットをEvent sourceに設定し、動作を確認してみます。

lambda log

ガンガン蓄積されているのがわかります。
（S3に出力されるまでにしばらくかかるのでご注意を。）

あとは、Log GroupにMetric Filterを用意して、CloudWatch Metricsにアラート設定すれば、
S3に出力されたログをイベントドリブンで監視できますね。

おまけ: Lambdaのトラブルシューティング

今回の記事を書くにあたり、いくつかハマったポイントがあったので、いくつかまとめてみます。

実行したリクエストが完了しない

当初、Lambdaのイベントハンドラ内で実行したリクエストが完了していないにも関わらずプロセスが終了してしまいました。
コンソールにはこんなログが表示されていました。たしかにリクエストが正常に完了している形跡がありません。

Process exited before completing request

これを回避するには、リクエストが完了したタイミングでちゃんとcontext.doneが呼ばれるようにしてあげます。

今回のLambdaコードを例にあげて説明します。

    var request = cloudwatchlogs.putLogEvents(param, function(err, data) {
        // main 
    }
NGパターン
    var request = cloudwatchlogs.putLogEvents(param, function(err, data) {
        // main 
    }
    context.done(null,'success');

こうすると、putLogEventsのリクエストが完了してcall back functionが実行される前にcontext.doneが実行されてしまいプロセスが停止してしまいます。

OKパターン
    var request = cloudwatchlogs.putLogEvents(param, function(err, data) {
        // main 
        context.done(null,'success');
    }

このようにすることで、ちゃんとcall back functionが実行されてからcontext.doneが呼ばれるようにしましょう。
if-else文等を使っている場合等、すべてのパスでcontext.doneが正しく実行されるようにご注意を。

オブジェクトの中身が見えない

これはLambdaというよりはnode.jsのノウハウになります。

今回のLambdaコードでもdataやerrなどいくつかオブジェクトが登場します。
デバッグ時にはオブジェクトの中身を全部見たいですよね。そこでこんなコードを書きがちです。

console.log ('error : '+err);

これを実行するとerrの中身が全部見える・・・かと思いきや、”Object”と省略されてしまい深い階層のプロパティが見えないことに気づきます。

そんなとき、util.inspectを使いましょう。
まずはrequire句で読み込みます。(Lambda環境で追加でモジュールをインストールする必要はありません。)

var util = require('util')

ログ出力時はこんな感じです。

console.log ('error : '+util.inspect(err,false,null));

これを実行するとerrの中身が全部見えます。トラブルシューティングに便利ですね。

2014
12/08
CATEGORY
AWS
Lambda
S3
コメントを書く

  1. トラックバックはまだありません。

コメントを残す