Cloud Functions(python)でたまにSSLEOFErrorが出てしまって悩んだ話

2023-09-07

エヌデーデー関口です。
自社のちょっとした処理をGoogle CloudのCloud Functionsを使って、pythonで実装しているのですが、たまにSSLEOFErrorが出てアラートが飛ぶということが何度かあったので、その原因を調査してみたという話です。

アーキテクチャ

アーキテクチャは以下のような内容です。自社内のとあるシステムからCSVをGoogle Cloud Storage(GCS)にアップロードし、それをトリガーにCloud Functionsが起動して、別のシステム(この場合はSalesforce)にデータを登録し、最後にその結果をGCSに戻すという簡単な仕組みです。

発生した問題

この処理、業務時間中には10分間隔で実行されて、ほとんどの場合正常に動作するのですが、月に数回次のようなエラーが出ていました。連続して起きる訳でもなく、次の10分後の処理は正常に動作するという感じです。

Exception on / [POST]
Traceback (most recent call last):
  File \"/layers/google.python.pip/pip/lib/python3.10/site-packages/urllib3/connectionpool.py\", line 703, in urlopen
    httplib_response = self._make_request(
  File \"/layers/google.python.pip/pip/lib/python3.10/site-packages/urllib3/connectionpool.py\", line 386, in _make_request
    self._validate_conn(conn)
  File \"/layers/google.python.pip/pip/lib/python3.10/site-packages/urllib3/connectionpool.py\", line 1042, in _validate_conn
    conn.connect()
  File \"/layers/google.python.pip/pip/lib/python3.10/site-packages/urllib3/connection.py\", line 414, in connect
    self.sock = ssl_wrap_socket(
  File \"/layers/google.python.pip/pip/lib/python3.10/site-packages/urllib3/util/ssl_.py\", line 449, in ssl_wrap_socket
    ssl_sock = _ssl_wrap_socket_impl(
  File \"/layers/google.python.pip/pip/lib/python3.10/site-packages/urllib3/util/ssl_.py\", line 493, in _ssl_wrap_socket_impl
    return ssl_context.wrap_socket(sock, server_hostname=server_hostname)
  File \"/layers/google.python.runtime/python/lib/python3.10/ssl.py\", line 513, in wrap_socket
    return self.sslsocket_class._create(
  File \"/layers/google.python.runtime/python/lib/python3.10/ssl.py\", line 1071, in _create
    self.do_handshake()
  File \"/layers/google.python.runtime/python/lib/python3.10/ssl.py\", line 1342, in do_handshake
    self._sslobj.do_handshake()
ssl.SSLEOFError: [SSL: UNEXPECTED_EOF_WHILE_READING] EOF occurred in violation of protocol (_ssl.c:1007)

ここまで読んで「はは〜ん、原因はアレだ」とおわかりの方は、もう読まなくても大丈夫ですw
その程度の記事です。今回は。

ともかく、このSSLEOFError(UNEXPECTED_EOF_WHILE_READING)は検索してもそれっぽい原因を示すような記事もなく、プロキシが途中にある場合とか、pythonのバージョンが古い場合などという話で、今回のケースには当てはまりそうにありません。

とある機能のテストでSSLEOFErrorが発生した

「う〜んよくわからないけど、たまにしか起きないし、次回の処理は正常に動くし、いいかあ」と思ってアラートが飛ばないようにして過ごしていましたが、とある別の機能のテストでこのエラーが再現したのです。

動作環境は上記と同じように、GCSからのファイルトリガーで複数のファイルをループしながら別の外部サービスに登録していくというものです。

そして、ローカルマシンでこのプログラムを実行したときには問題無かったのですが、Cloud Functionsに載せて試してみたところ、SSLEOFErrorが発生したのです。なぜだ！？

連続したエラーはすべてSSLEOFErrorが原因

原因を考えてみた

この処理はループ処理で何度も外部のサービスにファイルをPOSTする処理を含んでいます。とすれば・・・

  • エラーメッセージにconnectionpoolというワードも出てくるのでpoolが枯渇した？→いやメモリがあふれるようなこともないようだ
  • Cloud Functions、Cloud Runの割り当て制限に引っかかってる？→ドキュメント読む限りなさそう

ん〜、わからないのでサンプルプログラムを作ってみました。

サンプルプログラムで実験してみる

次のようなプログラムcallerとcalleeを作って、callerから何度も呼び出してみるということをやってみたのです。

呼び出し側の関数(caller)からは、URLを指定してメッセージをPOSTします。
下記のプログラムでは毎回requests.postとしていますが、同じ認証で何度も同じ場所にリクエストを投げるのであればsession = requests.Session()として、session.postとした方がkeepaliveが効いてくるので効率はいいです。Sessionはcookieを維持する以外の効果もあるというので、ご参考までに。

import requests
import traceback
import functions_framework
import google.auth.transport.requests
import google.oauth2.id_token

TARGET_URL = "呼び出し先の関数のURL"

@functions_framework.http
def caller(request):
    count = request.args.get('count')
    has_error = False
    request = google.auth.transport.requests.Request()
    id_token = google.oauth2.id_token.fetch_id_token(request, TARGET_URL)

    for i in range(0, int(count)):
        headers = {
            "Authorization": f"Bearer {id_token}"
        }

        post_data = {
            "message": "Hello World"
        }

        try:
            requests.post(url=TARGET_URL, headers=headers, json=post_data)
            print(f"{i} time")
        except Exception:
            print(traceback.format_exc())
            has_error = True

    return_message = "error" if has_error else "success"
    return {"status": return_message}

呼び出し先の関数(callee)は何かの処理をすることを想定して、1.5秒ほどのスリープを入れてみました。

import functions_framework
import time

@functions_framework.http
def callee(request):
    # Do something.
    time.sleep(1.5)
    return {}

関数呼び出しのパラメータに何回ループするかを載せます。（この場合は50回）

curl -H "Authorization: Bearer $(gcloud auth print-identity-token) "https://{Cloud FunctionsのURL}?count=50"

しばらくすると、upstream request timeout の文字が！
そして、Cloud Loggingの方にはSSLEOFErrorが出てきました！これだ！

判明した原因(というかオチ)

はい、ここまで来たらわかりましたね。原因はタイムアウトでした。お恥ずかしい。

たまにエラーが出ていた処理は、GCSからのイベントトリガーで動いており、通常だとそれほどの多くのデータ量を処理していないので、タイムアウトになっていることに気づけなかったのです。

関数のデプロイ時には--timeoutのパラメータに余裕をもった秒数をいれてください。
なお、指定しない場合は60秒、最大は第2世代でHTTPは3600秒、イベントドリブンは540秒まで設定できます。

(何度もループ処理するなら、Pub/Subに投げて並列処理した方がいいという意見もあると思いますので、その辺はいずれまた書きたいですね）

まとめ

Cloud Functionsでは、HTTPトリガー以外でも、タイムアウトに気を配って処理しましょう。

Google Cloud,TipsCloud Functions,Cloud Storage,Google Cloud Platform(GCP),Python,SSLEOFError

Posted by 関口 貴生