そうだ、教祖になろう。出エジプト記 第3章5節 LambdaのログをCloudWatch Logsに出力する

きよしこの夜

---

年末ですね。
年を越すというのは何か特別な感じがしてごちそうや保存食を買い込んで帰りたくなります。
冬ごもりの間の安心感を求めるからでしょうか。

安心感はシステムにも大切です。
第3章4節 Lambdaでサーバサイドを実装するでおおよその処理を実装しましたが、まだまだ実用には耐えません。
アプリケーションが動き始めると思いもよらぬ挙動をしたりして調査に時間がかかります。
調査の助けとなるよう、処理結果をトレースするログを仕込んでいきます。

このような構成です。

 

今回は2種類のログを仕込みます。

• エラーが発生したときのエラーの内容
• 関数が呼ばれたときの引数と戻り値の内容 

1つ目は開発中、運用中いずれでも重要です。
2つ目はどちらかというと開発中の調査用といった向きが強いですし量が多めになるので、運用が安定したら抑止してもいいでしょう。

すくいの御子は

---

Lambdaにおけるログ出力は非常に簡単です。
Pythonのloggingパッケージによる出力がCloud Watchに保存されます。
早速実装していきましょう。

メイン処理であるlambda_handler()関数の中をtryとexceptで囲みます。
捕捉したエラーをlogging.error()で出力します。

import os
import sys
sys.path.append(os.path.join(os.path.dirname(__file__), '../site-packages'))
sys.path.append(os.path.join(os.path.dirname(__file__), '.'))

import datetime
import json
import traceback
import logging
import gspread
from oauth2client.service_account import ServiceAccountCredentials
import settings
from lifereader import LifeReader
from responseformatter import ResponseFormatter

logger = logging.getLogger()
logger.setLevel(settings.LOGGER['level'])


def lambda_handler(event, context):
    try:

        reader = LifeReader()
        record = reader.random()

        formatter = ResponseFormatter()
        body = formatter.format(record)

        return {
            'statusCode': 200,
            'body': json.dumps(body, ensure_ascii=False)
        }

    except Exception as e:

        logger.error('{}\n{}'.format(str(e), traceback.format_exc()))

        return {
            'statusCode': 500,
        }

ちょっと乱暴なようですが、ここに来るのは予期してないエラーなのでこんなもんです。
setLevel()で設定しているのはsettings.pyに設定したログレベルです。

LOGGER = {'level': logging.INFO}

試しにエラーを起こしてみましょう。
Googleスプレッドシートのサービスアカウントキーを変更して認証エラーを発生させます。

なお、次回やるSNSによるエラー通知のために環境を色々いじったのでserversideという名前でLambdaアプリケーションを作り直しています。 

御母のむねに

---

CloudWatchに出力されているか確認してみましょう。
Lambda関数をCloud9からデプロイします。

CloudWatchの「ロググループ」を確認すると認証エラーが出力されていますね。  

LambdaからCloudWatchにログ出力するにはロググループを作ったり、ログイベントを出力したりする権限が必要なのですが、Cloud9がデプロイ するときによろしくロールを作ってくれているようです。 

眠りたもう

---

次に関数の呼び出しと戻り値のトレースログです。
エラーログと同じように仕込むと関数内が見づらくなって保守性が落ちるので、AOP=アスペクト指向で実装していきます。

Pythonに備わっているデコレーターという機構でログ出力処理を書きます。
ざっくり言うと開始ログ→関数コール→終了ログということをやります。
tracelogger.pyという名前でデコレーターを作ります。

import inspect
import time
import logging

logger = logging.getLogger(__name__)


def trace(func):
        try:
            is_method = inspect.getargspec(func)[0][0] == 'self'
        except:
            is_method = False

        if is_method:
            func_name = '{} {}.{}'.format(func.__module__,
                                          args[0].__class__.__name__,
                                          func.__name__)
        else:
            func_name = '{} {}'.format(func.__module__, func.__name__)

        logger.info('[{}] args[{}, {}]'.format(func_name, args[1:], kwargs))
        start = time.time() * 1000
        result = func(*args, **kwargs)
        finish = time.time() * 1000 - start
        logger.info('[{}] time[{}] result[{}]'.format(func_name, round(finish),
                                                      result))

        return result

    return _trace

funcが呼ばれる関数で前後でログを出力しています。
開始ログは引数を、終了ログは処理時間（ミリ秒）と戻り値を一緒に出力してます。
関数名は

• インスタンスメソッドの場合：[モジュール名 クラス名.メソッド名]
• その他の関数：[モジュール名 関数名]

にしています。

できたデコレーターを各モジュールでインポートして、トレースしたいメソッドにアノテーションをくっつけます。  

インスタンスメソッドの場合はこう。

from tracelogger import trace


class LifeReader():

    @trace
    def random(self, ):
    # 処理

メイン処理もこうです。

from tracelogger import trace


@trace
def lambda_handler(event, context):
    # 処理

いとやすく

---

では、settings.pyの設定を正常に戻して実行してみましょう。
各関数の引数、処理時間、戻り値が出力されていますね。
これで安心して年を越せそうです。  

次回は出力したログからエラー通知メールを送れるようにしたいと思います。