AWS X-Ray SDK for PythonでOSError: [Errno 90] Message too longのエラーが出たので調査/対応してみた

岩田智哉

2021.12.20

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

MAD事業部@大阪の岩田です。先日Lambdaのエラーを監視＆通知しているSNSトピックからOSError: [Errno 90] Message too longというエラーが発生したという通知が飛んできました。このエラーの原因を調査&対応したので対応方法についてご紹介します。

概要

エラーが発生していたのは夜間バッチ処理のStep Functionsから起動されるLambdaです。RDBに保存されたデータを集計し、集計後のデータを再度RDBに書き戻すような処理を実行しています。このLambdaのログにFailed to send entity to Daemon.というエラーメッセージが出力され、これがエラー検知の仕組みに引っかかっていました。

ログに出力されていたスタックトレースはこんな感じでした

Traceback (most recent call last):
File \"/opt/python/aws_xray_sdk/core/emitters/udp_emitter.py\", line 41, in send_entity
self._send_data(message)
File \"/opt/python/aws_xray_sdk/core/emitters/udp_emitter.py\", line 63, in _send_data
self._socket.sendto(data.encode('utf-8'), (self._ip, self._port))
OSError: [Errno 90] Message too long"}

どうもUDPのパケットサイズ上限に抵触しているような気配がします

ググってみる

とりあえずエラーメッセージを元にググってみたところ、以下の情報がヒットしました。

対象Lambdaにxray_recorder.configure(streaming_threshold=0)を追加し、トレースデータをバッチ送信せずサブセグメントごとに個別送信すればメッセージサイズの上限に引っかからずに済みそうです。AWS Lambda Powertools (Python)でも上記の対応が導入されていました。

is_cold_start = True
logger = logging.getLogger(__name__)
# Set the streaming threshold to 0 on the default recorder to force sending
# subsegments individually, rather than batching them.
# See https://github.com/awslabs/aws-lambda-powertools-python/issues/283
aws_xray_sdk.core.xray_recorder.configure(streaming_threshold=0)

https://github.com/awslabs/aws-lambda-powertools-python/pull/284/files

ということでLambdaのコードを修正し、翌日のバッチ処理で様子を見ることにしました。

streaming_thresholdを0にしても改善しなかった

これで無事に問題が解決しただろう...と思ったのですが翌日もエラー通知のメールが飛んできました。なぜ...と思い、もう少し詳細を調査することにしました。

AWS X-Ray SDK for Pythonのコードを確認するとエラーが発生している箇所の前後は以下のようなコードになっていました。

    def send_entity(self, entity):
        """
        Serializes a segment/subsegment and sends it to the X-Ray daemon
        over UDP. By default it doesn't retry on failures.

        :param entity: a trace entity to send to the X-Ray daemon
        """
        try:
            message = "%s%s%s" % (PROTOCOL_HEADER,
                                  PROTOCOL_DELIMITER,
                                  entity.serialize())

            log.debug("sending: %s to %s:%s." % (message, self._ip, self._port))
            self._send_data(message)
        except Exception:
            log.exception("Failed to send entity to Daemon.")

self._send_data(message)の前にlog.debugが埋め込まれているので、DEBUGレベルのログを出力すればどういう情報を送信しようとしてエラーになっているのかが分かりそうです。対象のLambdaに以下のコードを追加しました。

logging.getLogger('aws_xray_sdk').setLevel(logging.DEBUG)

これでAWS X-Ray SDK for PythonからはDEBUGレベルのログまで出力されるようになります。この状態でLambadを実行するとエラーログの直前には以下のようなログが出力されていました。

"sending: {\"format\":\"json\",\"version\":1}\n{\"id\": \"266d5575e6d637ee\", \"name\": \"hogehoge.abcdefghij.ap-northeast-1.rds.amazonaws.com\", \"start_time\": 1639993720.4766362, \"parent_id\": \"8a347a31f141d234\", \"in_progress\": false, \"trace_id\": \"1-61c05176-3afe80c6161eb00720cc563c\", \"type\": \"subsegment\", \"namespace\": \"remote\", \"sql\": {\"url\": \"mysql+pymysql://db_user@hogehoge.abcdefghij.ap-northeast-1.rds.amazonaws.com/db?charset=utf8&program_name=hoge-function\", \"user\": \"db_user\", \"database_type\": \"mysql\", \"driver_version\": \"pymysql\", \"database_version\": \"5.7.33\", \"sanitized_query\": \"INSERT INTO tab(col1, col2) VALUES(%(col1_m1)s,%(col2_m1)s),(%(col1_m2)s,%(col2_m2)s),.... \"}, \"end_time\": 1639993720.4975338} to 169.254.79.129:2000."

集計後のデータをまとめてINSERTするSQLが長すぎてメッセージサイズに引っかかっていたようです。MySQL側の制限に抵触しないように一定件数でINSERT文を分割実行するような考慮は実装していましたが、MySQLの上限よりもはるかに早くX-Ray SDK(というよりはLambda実行環境のUDPパケットサイズ上限)の上限に抵触してしまったようです。