第2世代Cloud Functionsのタイムアウト時の挙動について注意したいこと

Cloud Monitoringでログベースのアラートを作成する際は気をつけたほうが良いかも。

#Google Cloud (GCP)

#Cloud Functions

#Cloud Logging

#Pub/Sub

#Python

ニューシロ

2023.12.07

クラスメソッド株式会社データアナリティクス事業本部所属のニューシロです。
今回はGoogle Cloudのサービスである第2世代Cloud Functionsのタイムアウト時の挙動について注意したいことについてまとめました。

前提

タイムアウトとは

以下公式ドキュメントからの引用です。

関数の実行時間はタイムアウト時間によって制限されます。この時間は、関数のデプロイ時に指定できます。デフォルトでは、関数は 1 分（60 秒）後にタイムアウトしますが、この期間は延長できます。

引用元：関数のタイムアウト | Google Cloud Functions に関するドキュメント

Cloud Functionsの実行時間には制限があります。それがタイムアウト時間です。

トリガーによる最大タイムアウト時間の違い

以下公式ドキュメントからの引用です。

Cloud Functions（第 2 世代）の最大タイムアウト時間は、HTTP 関数の場合は 60 分（3,600 秒）、イベントドリブン関数の場合は 9 分（540 秒）です。

引用元：関数のタイムアウト | Google Cloud Functions に関するドキュメント

第2世代Cloud Functionsはデフォルトではタイムアウト時間は1分(60秒)ですが、設定によって伸ばすことができます。HTTPトリガーとイベントトリガーでそれぞれ設定できる最大値は違い、HTTPトリガーは最大60分、イベントトリガーは最大9分です。

本題

検証項目

それでは、タイムアウトエラーを実際に出力させ、その結果を元に注意したいことについて確認していきたいと思います。

全ての検証環境について、共通している項目は以下の通りです。

タイムアウト時間はデフォルトの1分(60秒)で設定
Cloud Functionsは第2世代を選択
ランタイムはPython3.11

それでは、以下の3点について検証していきましょう。

1. HTTPトリガーで70秒かかるコードを実行してタイムアウトエラーを発生させる
2. HTTPトリガーで1000秒かかるコードを実行してタイムアウトエラーを発生させる
3. イベントトリガーで1000秒かかるコードを実行してタイムアウトエラーを発生させる

1. HTTPトリガーで70秒かかるコードを実行してタイムアウトエラーを発生させる

第2世代Cloud FunctionsをHTTPトリガーでデプロイします。
コード内でtime.sleep()を用いて意図的にタイムアウトを出力します。
今回はtime.sleep(70)を用いることで、Cloud Functionsの実行時間が70秒程度かかるように設定します。

参照：time --- 時刻データへのアクセスと変換 — Python 3.12.0 ドキュメント - time.sleep(secs)

以下の通り、関数の開始時にはログにStart.と出力し、70秒後ログにEnd.と出力するコードを用います。 Cloud Functionsの実行時間が70秒に対しタイムアウト時間60秒のため、タイムアウトになるはずです。

import time

import functions_framework


@functions_framework.http
def timeout_test(request):

    print("Start.")
    # 70秒待機する
    time.sleep(70)
    print('End.')

    return 'OK'

functions-framework==3.*

Cloud Shellでcurlコマンドを入力してCloud Functionsを起動してみます。
60秒後、ログでは以下のようなエラーログが出力されます。

画像が小さいのですが、The request has been terminated because it has reached the maximum request timeout.と記載があります。これで、想定通りCloud Functionsがタイムアウトになっていることがわかりました。

しかし、想定外のログも出力されています。ログの流れを見てみましょう。

赤枠では60秒後、レスポンス504（タイムアウトエラー）が返ってきており、タイムアウトしていることがわかります。このログに先ほどの画像にあるThe request has been terminated because it has reached the maximum request timeout.も記載されていました。

しかし、青枠では70秒後に実行されるはずのprint('End.')まで実行されていることが確認できます。
60秒で処理が終了されるならprint('End.')は実行されないはずです。

タイムアウト後も処理が続く場合がある

実はCloud Functionsでは、タイムアウト後も処理が続く場合があるようです。
こちらは私の想定外の挙動でしたが、ドキュメントに記載がありました。以下公式ドキュメントからの引用です。

場合によっては、一時停止した処理がバックグラウンドで続行されたり、後続のリクエストで再開されることがあります。

引用元：関数のタイムアウト | Google Cloud Functions に関するドキュメント

今回のようにタイムアウト時間後も処理が続行されることもあるようです。
注意したいこととして、タイムアウト後に必ず処理が続行し、完了するわけではありません。次の検証で確認しましょう。

2. HTTPトリガーで1000秒かかるコードを実行してタイムアウトエラーを発生させる

コードを1行だけ変えてみます。time.sleep(70)をtime.sleep(1000)に変えて1000秒待機させてみます。

import time

import functions_framework


@functions_framework.http
def timeout_test(request):

    print("Start.")
    # 1000秒待機する
    time.sleep(1000)
    print('End.')

    return 'OK'

実行後30分（1800秒）ほど待って、ログを確認しました。

今回はprint('End.')までは実行できていません。先ほどと違い、処理が途中で終了しています。

タイムアウト後の処理は続かない場合もある

Cloud Functionsのドキュメントにはこのような記載もあります。

一時停止した作業が再開するかどうかはわからないため、この動作には依存しないでください。

引用元：関数のタイムアウト | Google Cloud Functions に関するドキュメント

タイムアウト後の処理については保証されていないようです。気をつけましょう。

3. イベントトリガーで1000秒かかるコードを実行してタイムアウトエラーを発生させる

今まではHTTPトリガーでしたので、最後にイベントトリガーを用いた検証です。

コードはほぼ同じで、Pub/Subトリガーで実装します。
Cloud Functionsのタイムアウト時間は60秒に設定し、コード内のtime.sleep(1000)でタイムアウトを発生させましょう。

import time

import functions_framework


@functions_framework.cloud_event
def timeout_test(cloud_event):

    print("Start.")
    # 1000秒待機する
    time.sleep(1000)
    print('End.')

functions-framework==3.*

Pub/Subトピックに適当なメッセージを送ってCloud Functionsを起動させます。
Cloud Functions起動後30分（1800秒）ほど待ってからログを見てみます。

先ほどのHTTPトリガーでのログと比較してみましょう。
print('End.')まで起動できていないことまでは同じですが、Cloud Functionsがタイムアウト時間60秒に達した際、レスポンスがタイムアウト時の504ではなく200で返ってきています。
レスポンス200はリクエストが正常に終了したことを示すコードですので、エラーログ扱いではありません。
つまり、HTTPトリガーと違いタイムアウトについてのエラーログは出力されていません。