イベントトリガーCloud FunctionsのタイムアウトをCloud Loggingで検出するクエリ
2024.03.24クラスメソッド株式会社データアナリティクス事業本部所属のニューシロです。
今回はGoogle Cloudのサービスである第2世代Cloud FunctionsのタイムアウトをCloud Loggingで検出するクエリを作成してみました。
用途としては、Cloud Monitoringのログベースのアラートでの使用を想定しています。
前提
タイムアウトとは
以下公式ドキュメントからの引用です。
関数の実行時間はタイムアウト時間によって制限されます。この時間は、関数のデプロイ時に指定できます。デフォルトでは、関数は 1 分（60 秒）後にタイムアウトしますが、この期間は延長できます。
Cloud Functionsの実行時間には制限があります。それがタイムアウト時間です。
Cloud Functionsのタイムアウトで注意すべきこと
Cloud Functionsはトリガーによってはタイムアウト時の挙動が異なります。詳しくは以下の記事を参考にして下さい。 特に、タイムアウト時にエラーログが出力されないことがある点には注意しましょう。
やりたいこと
使用しているCloud Functionsをモニタリングする際、Cloud Monitoringのログベースのアラートを作成してエラーを検出することがあるかと思います。 この場合、エラーログのみを出力するクエリを設定することが多いと思いますが、前述の通りタイムアウトはエラーログとして検出できないことがあります。
タイムアウト発生時にはCloud Functionsの処理は正常に終了していない可能性がありますので、こちらもCloud Monitoringアラートで検知しておきたいです。 そのためにも、エラーログまたはタイムアウト時のログ両方を出力するようなCloud Loggingのクエリを作成していきたいと思います。
本題
検証
今回は、イベントトリガーの中でもPub/Subトリガーに絞って検証します。
Cloud Functionsの第1世代、第2世代についてそれぞれ検証します。
他の設定を箇条書きにしておきます。
- タイムアウト時間は1分(60秒)
- ランタイムはPython3.12
第2世代イベントトリガーCloud Functionsでのタイムアウト
それではタイムアウトエラーを実際に出力させて、結果を元にCloud Loggingのクエリを考えてみます。
以下のコードを使用します。
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.*
Cloud Functionsのタイムアウト時間は60秒に設定しておりますので、コード内のtime.sleep(1000)でタイムアウトが発生するはずです。
Pub/Subトピックに適当なメッセージを送ってCloud Functionsを起動させます。
Cloud Functions起動後しばらく待ってからログを見てみます。
処理が最後まで正常に実行されていればコード末尾のprint('End.')まで実行されているはずですが、ログには表示されていません。
よって想定通りタイムアウトが発生していることがわかりますが、タイムアウトを示すようなログも出ていません。
ここで、ログに表示されているhttpRequest.latencyの値に着目します。
httpRequest.latencyがタイムアウト時間の60秒に近い値（今回だと60.001s）と表示されています。
httpRequest.latencyがタイムアウト時間と近い値になっていれば、タイムアウトしたと判断できそうです。この場合のログをキャッチするクエリを作成してみます。
まず、このCloud Functionsのログを表示するクエリを確認します。
Cloud Functionsのコンソール画面のログタブをクリックし、ログ エクスプローラで表示タブをクリックすることでこの画面に移動できます。
このクエリだと、Cloud Functionsalert-test-gen2に関するログが全て出力されます。
やりたいこととしては、エラーログまたはタイムアウトのログのみ検出することです。ログのhttpRequest.latency箇所をクリックして、次の値以上を表示をクリックします。
するとクエリに9, 10行目の2行が追加されます。
これを利用しましょう。60秒に近い値を拾えるように、"59000ms"以上に設定しましよう。
また、Cloud Monitoringアラートでタイムアウト以外のエラーログも拾いたいので、クエリはエラーログまたはhttpRequest.latencyが"59000ms以上を拾うようにします。
（コピペ用にこちらも記載します）
(resource.type = "cloud_function" resource.labels.function_name = "alert-test-gen2" resource.labels.region = "asia-northeast1") OR (resource.type = "cloud_run_revision" resource.labels.service_name = "alert-test-gen2" resource.labels.location = "asia-northeast1") (severity>=ERROR OR (httpRequest.latency>="59000ms" OR jsonPayload.latency>="59000ms"))
できました。あとはこのクエリのままログベースのアラートを作成しましょう。
作成方法は割愛しますが、コンソール画面から簡単に作成できます。Cloud Loggingのアラートを作成をクリックすると作成を開始できます。
このクエリでCloud Functionsのエラーログだけでなく、タイムアウトもCloud Monitoringアラートで検出できます。
参考にしていただけると幸いです。
第1世代イベントトリガーCloud Functionsでのタイムアウト
第1世代Cloud Functionsでも確認してみます。
第2世代とほぼ同じコードでタイムアウトを発生させます。
import time
def timeout_test(event, context):
print('Start.')
# 1000秒待機する
time.sleep(1000)
print('End.')
Pub/Subトピックに適当なメッセージを送ってCloud Functionsを起動させます。
Cloud Functions起動後しばらく待ってからログを見てみます。
こちらもエラーログが出力されません。しかし、ログとして以下のメッセージが出力されました。
Function execution took 60000 ms, finished with status: 'timeout'
このメッセージを利用しましょう。秒数はタイムアウト時間によって異なりますので、後半のfinished with status: 'timeout'をログでキャッチするようにクエリを作成します。
resource.type = "cloud_function"
resource.labels.function_name = "alert-test-gen1"
resource.labels.region = "asia-northeast1"
(severity>=ERROR OR
SEARCH("`finished with status: 'timeout'`"))
後のCloud Monitoringアラートの作成については第2世代と同一のため割愛します。
世代で分けて対応していきましょう。
最後にまとめ
テストするまでは、タイムアウトもエラーログとして出力されると思っておりました。
それぞれのエラーケースにおいて、アラートが出力されることは事前に確認しておきましょう。
