Pythonの関数の引数と戻り値のログ出力をデコレータで部品化する（Google Cloud Functions）

データアナリティクス事業本部、池田です。
ログを吐いておけば良かったと思う日って、あると思います。

私はけっこうログ出力を書く派なのですが、 複数人で実装をしていると書き方の好みが違ったり頻度も違ったりします。 （コーディング規約を決めれば良いって話かもしれませんが。）
あまり労力をかけずにその辺を上手くやりたいと思い、 まずは、Pythonの関数を呼び出す時に渡す引数と、 その関数の戻り値のログ出力を デコレータ で部品にしてみました。

今回は実行環境として、Google Cloudの Cloud Functions を使います（Pythonは3.10）。 Cloud Functionsを使いますが、デコレータの部分はPythonであれば他の環境でも動くはずです。たぶん。

Cloud FunctionsのLoggingライブラリについては、 ↓で以前ブログにしており、このCloud Functions関数を修正するかたちで実装しています。

Cloud FunctionsでGoogle Cloud Python Loggingライブラリを使ってみる（初心者向け）

※関数という言葉がややこしいのですが、このブログの中では、 Cloud Functionsのデプロイする単位は「Cloud Functions関数」、 Pythonの def foo(): の方を「関数」と記載するようにします。

デコレータ部分の実装（部品）

（参考にしたサイトはブログの最後にまとめて記載しておきます。）

my_common というフォルダに my_log という名前（デコレータ名）で実装しました。

my_common/log.py

from functools import wraps


def my_log(logger):
    def decorator_fn(fn):
        @wraps(fn)
        def wrap_fn(*args, **kwargs):
            local_args = locals()
            logger.debug(f"{fn.__name__} WAS CALLED: {str(local_args)}")
            return_val = fn(*args, **kwargs)
            logger.debug(f"{fn.__name__} FINISHED: {str(return_val)}")
            return return_val
        return wrap_fn
    return decorator_fn

デコレータでloggerを受け取って、ローカルの変数と戻り値をデバッグレベルでログ出力するようにしています。

私はかなり簡単な実装にしてしまいましたが、 もっといろいろやっている記事 もあったので、読み解いてみて下さい。

デコレータを使う部分の実装（本体）

本体のPythonコードです。
関数の前に @my_log(logger) とデコレータを書くだけでログを出力してくれます。

main.py

import base64
import os
import functions_framework
from logging import getLogger, DEBUG
import google.cloud.logging
from my_common.log import my_log

logging_client = google.cloud.logging.Client()
logging_client.setup_logging()
logger = getLogger(__name__)
logger.setLevel(DEBUG)


@my_log(logger)
def sub_fn(sample_param_str, sample_param_num):
    try:
        logger.info("info at try")
        _ = 1 / 0
    except Exception:
        logger.error("error at except")
        # raise
    finally:
        logger.debug("debug at finally")

    return "sub_fn()の戻り値"


@my_log(logger)
@functions_framework.http
def sample_logging_fn_v2(request):
    pubsub_message = base64.b64decode(request.get_json(silent=True)["message"]["data"]).decode("utf-8")
    logger.info(f"pubsub_message: {pubsub_message}")

    logger.debug(request.get_json(silent=True))

    logger.warning(f"env: {os.getenv('ENV_VAR')}")

    _ = sub_fn("サンプル引数", 1234)

    return "OK"

エントリポイントである sample_logging_fn_v2() 関数と、 それから呼び出される sub_fn() の引数＆戻り値がデコレータによって、 ログ出力されるはずです。

1つの関数に対する複数のデコレータは、 下から適用されるそうです。

↓Cloud Functionsでのロギングのための依存関係。

requirements.txt

functions-framework>=3.0
google.cloud.logging>=3.2.0

↓Cloud Functionsをデプロイするためのスクリプト。

deploy.sh

gcloud functions deploy sample-logging-fn-v2 \
--gen2 \
--region asia-northeast1 \
--runtime python310 \
--entry-point=sample_logging_fn_v2 \
--trigger-http \
--allow-unauthenticated \
--timeout 30 \
--memory 128MiB \
--set-env-vars ENV_VAR=環境変数からの値

※ --allow-unauthenticated は「未認証の呼び出しを許可」する設定です。 簡略化するために有効にしましたが、利用には注意が必要です。

デプロイ～動かしてみる

前章のdeploy.shを実行することで、 Cloud Functions関数をデプロイできます。
↓こんな感じになります。

さくっと Cloud Pub/Sub を作って呼び出します。

# トピックの作成
gcloud pubsub topics create sample_logging_topic

# Cloud Functions関数のURLを取得
PUSH_ENDPOINT_URI=`gcloud functions describe sample-logging-fn-v2 --gen2 --region asia-northeast1 --format="value(serviceConfig.uri)"`

# サブスクライブ登録
gcloud pubsub subscriptions create gcf-sample-logging-fn-v2-subscription \
--topic=sample_logging_topic \
--expiration-period=never \
--push-endpoint=$PUSH_ENDPOINT_URI

※サブスクリプションが再実行を繰り返してしまうことがあるので、 簡略化のため省略しましたが、 Cloud Functions関数の内容によってはデッド レタリングの設定などが必要そうです。

↓のコマンドでPub/Subにメッセージを発行すると、デプロイしたCloud Functions関数が呼び出されます。
gcloud pubsub topics publish sample_logging_topic --message="pubsubのメッセージ3"

↓ ログエクスプローラ でログを参照するとこんな感じ。

各Python関数の呼び出しや終了時にログが出力されています！！！

本体のデコレータを使う側は、とても少ない労力でログを出力できるようになりました。
利用に当たって注意が必要と思うのは、 例えばアクセスキーなど、ログ出力したくない情報を関数の間で受け渡しする場合です。
その場合は、部品の方で除外するようなロジックを追加するか、 デコレータを付けないようにするような注意が必要です。

おわりに

デコレータって便利ですね。

関連情報/参考にさせていただいたページ

• decorator
• How can I log a functions arguments in a reusable way in Python?
• python3:全ての関数の呼び出しと終了のログを取得する方法
• A better way to logging in Python
• 複数のデコレータを適用するPythonサンプルプログラム
• Pythonのデコレータ関数の使いかた、複数のデコレータを利用する方法等、まとめました。
• Cloud FunctionsでGoogle Cloud Python Loggingライブラリを使ってみる（初心者向け）
• 第1世代Pub/SubトリガーのGoogle Cloud Functionsを第2世代のHTTPトリガーに書き換えてみた