LoginSignup
1
0

More than 1 year has passed since last update.

@akkii__

loggingを使って独自にカスタマイズしたLambda実行ログを残す

Posted at

はじめに

AWS Lambdaを実行した際、いい感じのログを残してデバッグしやすくしたいと思ったのが始まりです。
はじめはprint関数でログを残していましたが、より高性能にログを残せるloggingライブラリがあるので、こちらを使ってログを出力していきたいと思います。

loggingの紹介

loggingは、Pythonの標準ライブラリのうちの一つで、ログ出力に特化した機能を持っています。
print関数でログを残すより多くの機能を使えるので、ぜひ使える様になっておきたいライブラリの一つです。

ログレベル

loggingには5つのログレベルがあり、目的に合わせて使い分けます。

ログレベル 概要
DEBUG デバッグログ。デバッグ用途等
INFO 情報ログ。想定内の事象が起こった等
WARNING 警告ログ。想定外の事象が起こった、もうすぐ起こりそう等
ERROR エラーログ。一部機能が使えない等
CRITICAL 致命的エラーログ。プログラムの実行が続けられない等

各ログレベルのログを出力します。

logging_test1.py
import logging

# 各ログレベルを出力
logging.debug('DEBUG Level')
logging.info('INFO Level')
logging.warning('WARNING Level')
logging.error('ERROR Level')
logging.critical('CRITICAL Level')

実行結果

% python logging_test1.py
> WARNING:root:WARNING Level
> ERROR:root:ERROR Level
> CRITICAL:root:CRITICAL Level

WARNING以上のログしか出力されていません。
実はloggingの標準ではWARNINGレベル以上のログしか出力されない様になっています。

DEBUGレベルのログも出力するには、設定を変更する必要があります。

logging_test2.py
import logging

# 出力するログレベルを設定
logging.basicConfig(level=logging.DEBUG)

# 各ログレベルを出力
logging.debug('DEBUG Level')
logging.info('INFO Level')
logging.warning('WARNING Level')
logging.error('ERROR Level')
logging.critical('CRITICAL Level')
実行結果
% python logging_test2.py
> DEBUG:root:DEBUG Level
> INFO:root:INFO Level
> WARNING:root:WARNING Level
> ERROR:root:ERROR Level
> CRITICAL:root:CRITICAL Level

今度は全てのログレベルが出力されています。

この設定はlogging全体にかかっているので、loggerインスタンスを生成して個別に設定します。

logging_test3.py
import logging

# logging全体の出力するログレベルを設定
logging.basicConfig(level=logging.DEBUG)

# 1つ目のloggerはDEBUGレベル以上を出力
first_logger = logging.getLogger('first')
first_logger.setLevel(logging.DEBUG)

# 2つ目のloggerはWARNINGレベル以上を出力
second_logger = logging.getLogger('second')
second_logger.setLevel(logging.WARNING)

# 各ログレベルを出力
for logger in [first_logger, second_logger]:
    logger.debug('DEBUG Level')
    logger.info('INFO Level')
    logger.warning('WARNING Level')
    logger.error('ERROR Level')
    logger.critical('CRITICAL Level\n')
実行結果
% python logging_test3.py
> DEBUG:first:DEBUG Level
> INFO:first:INFO Level
> WARNING:first:WARNING Level
> ERROR:first:ERROR Level
> CRITICAL:first:CRITICAL Level
> 
> WARNING:second:WARNING Level
> ERROR:second:ERROR Level
> CRITICAL:second:CRITICAL Level
>

1つ目のlogger(first_logger)はDEBUGレベル以上、2つ目のlogger(second_logger)はWARNINGレベル以上のログが出力されています。

ログのフォーマット

これまで出力されていたログの内容については触れてきませんでした。
以下は先の出力結果を切り取ったものです。

ログ例
DEBUG:first:DEBUG Level

標準ロガーのフォーマットは%(levelname)s:%(name)s:$(message)で表されます。

属性名 フォーマット 説明
asctime %(asctime)s ログレコードが出力された時刻
levelname %(levelname)s ログレベル
name %(name)s 設定したloggerの名前
message %(message)s ログメッセージ

その他たくさんありますが、下記ページを参考ください。

フォーマットの変更には、ハンドラを作成して設定を追加します。
ハンドラはロガーに紐づけることにより、ロガーが受け取ったログレコードを任意の場所へ出力します。
これまでハンドラを設定していませんでしたが、デフォルトでは標準エラー出力へログが出力されていました。

levelname asctime messageを入れたフォーマットでログを出力してみます。
また、最終目標のLambdaのログ(CloudWatchログ)は標準出力へ流せばログ出力されます。

logging_test4.py
import logging
import sys

logger = logging.getLogger('hoge')
logger.setLevel(logging.DEBUG)

# ログを標準出力へ出力するハンドラを作成
handler = logging.StreamHandler(sys.stdout)
# フォーマットを作成し、ハンドラに設定する
formatter = logging.Formatter('[%(levelname)s]\t%(asctime)s\t%(message)s')
handler.setFormatter(formatter)
# ハンドラをロガーに設定
logger.addHandler(handler)

logger.debug('DEBUG Level')
logger.info('INFO Level')
logger.warning('WARNING Level')
logger.error('ERROR Level')
logger.critical('CRITICAL Level')
実行結果
% python logging_test4.py
> [DEBUG] 2023-03-26 00:54:17,499 DEBUG Level
> [INFO]  2023-03-26 00:54:17,499 INFO Level
> [WARNING]       2023-03-26 00:54:17,499 WARNING Level
> [ERROR] 2023-03-26 00:54:17,499 ERROR Level
> [CRITICAL]      2023-03-26 00:54:17,499 CRITICAL Level

綺麗に出力されました。

Lambdaのログとlogging

Lambdaのログをloggingを使って出力する場合、Lambdaには既に標準のロガーが定義されています。

lambda_function.py
import logging
import sys

# Lambda標準のロガーを取得し、出力するログレベルを変更
logger = logging.getLogger()
logger.setLevel(logging.DEBUG)

# Lambdaハンドラ
def lambda_handler(event, context):
    logger.debug('DEBUG Level')
    logger.info('INFO Level')
    logger.warning('WARNING Level')
    logger.error('ERROR Level')
    logger.critical('CRITICAL Level')
CloudWatchログ出力
START RequestId: 0ed1dab9-xxxx-xxxx-xxxx-xxxxxxxxxxxx Version: $LATEST
[DEBUG]	2023-03-26T02:31:22.022Z	0ed1dab9-xxxx-xxxx-xxxx-xxxxxxxxxxxx	DEBUG Level
[INFO]	2023-03-26T02:31:22.022Z	0ed1dab9-xxxx-xxxx-xxxx-xxxxxxxxxxxx	INFO Level
[WARNING]	2023-03-26T02:31:22.022Z	0ed1dab9-xxxx-xxxx-xxxx-xxxxxxxxxxxx	WARNING Level
[ERROR]	2023-03-26T02:31:22.022Z	0ed1dab9-xxxx-xxxx-xxxx-xxxxxxxxxxxx	ERROR Level
[CRITICAL]	2023-03-26T02:31:22.022Z	0ed1dab9-xxxx-xxxx-xxxx-xxxxxxxxxxxx	CRITICAL Level
END RequestId: 0ed1dab9-xxxx-xxxx-xxxx-xxxxxxxxxxxx

フォーマットが[%(levelname)s\t%(asctime)s\t%(aws_request_id)s\t%(message)sの形で並んでいます。

aws_request_id属性が見慣れませんが、これは実行したLambdaのIDです。
Lambdaが実行されるごとに固有のIDが割り振られるので、これを使ってCloudWatchLogsのログのインサイトで抽出することができます。

fields @timestamp, @requestId, @message
| filter @requestId like '0ed1dab9'
| display @timestamp, @requestId, @message
| sort @timestamp

ログのインサイト結果
image.png
特定のrequestIdのログを抽出できました。

Lambdaのログをカスタムする

さて、本題のLambdaのログを好みのフォーマットに変えていきます。

以前の方法では、ハンドラを生成してフォーマットを設定しました。

logging_test4.py
import logging
import sys

logger = logging.getLogger('hoge')
logger.setLevel(logging.DEBUG)

# ログを標準出力へ出力するハンドラを作成
handler = logging.StreamHandler(sys.stdout)
# フォーマットを作成し、ハンドラに設定する
formatter = logging.Formatter('[%(levelname)s]\t%(asctime)s\t%(message)s')
handler.setFormatter(formatter)
# ハンドラをロガーに設定
logger.addHandler(handler)

logger.debug('DEBUG Level')
logger.info('INFO Level')
logger.warning('WARNING Level')
logger.error('ERROR Level')
logger.critical('CRITICAL Level')

しかしLambdaには定義されたハンドラが既に作られています。

Lambda標準ハンドラから出力されたログ
[DEBUG]	2023-03-26T02:31:22.022Z	0ed1dab9-b45f-4427-b511-11f7c0711d87	DEBUG Level

Lambda標準ハンドラには独自に定義されたLambda実行IDが存在していたので、Lambda標準ハンドラのフォーマットを変更します。
このとき、Lambda標準ハンドラは存在しているので、ロガーに対してhandlers属性を参照することでLambda標準ハンドラを抽出することができます。

また、フォーマットには実行ファイル名、関数名、行番号を追記してよりデバッグしやすくなる様変更しました。

lambda_handler.py
import logging
import sys

logger = logging.getLogger()
logger.setLevel(logging.DEBUG)

# フォーマットの作成
formatter = logging.Formatter(
  '[%(levelname)s]\t%(asctime)s.%(msecs)dZ\t%(aws_request_id)s\t%(filename)s\t%(funcName)s\t%(lineno)d\t%(message)s\n',
  '%Y-%m-%dT%H:%M:%S'
)
# Lambda標準ハンドラに対してフォーマットをセット
# (既に生成されているLambda標準ハンドラを抽出)
for handler in logger.handlers:
    handler.setFormatter(formatter)

# Lambdaハンドラ
def lambda_handler(event, context):
    logger.debug('DEBUG Level')
    logger.info('INFO Level')
    logger.warning('WARNING Level')
    logger.error('ERROR Level')
    logger.critical('CRITICAL Level')
CloudWatchログ出力
[DEBUG]	2023-03-26T03:43:30.378Z	xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx	lambda_function.py	lambda_handler	18	DEBUG Level
[INFO]	2023-03-26T03:43:30.378Z	xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx	lambda_function.py	lambda_handler	19	INFO Level
[WARNING]	2023-03-26T03:43:30.378Z	xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx	lambda_function.py	lambda_handler	20	WARNING Level
[ERROR]	2023-03-26T03:43:30.378Z	xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx	lambda_function.py	lambda_handler	21	ERROR Level
[CRITICAL]	2023-03-26T03:43:30.378Z	xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx	lambda_function.py	lambda_handler	22	CRITICAL Level

これで独自にカスタマイズしたログ出力をすることができました。

参考

1
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
1
0