Lambdaを使ったサーバレス構成の社内アプリのデバッグのためにX-Rayを使ってみた

12月も終盤、2019年も終盤、令和元年も終盤です。みなさんいかがお過ごしですか。ソーシャルゲーム事業部ゲーム技研の谷脇です。

この記事はTech KAYAC Advent Calendar 2019の24日目の記事です。

Migration Trackの方で結構書いたので、こっちは何書こうかなーとなったんですが、あえて小ネタでAWS Lambda使う時のTipsな感じで行きます。

AWS Lambdaのデバッグがしんどい件

僕はサーバレス・コンテナ以前からWebのサーバ開発をやっている人間なもので、動いているやつをダイレクトにソースコードいじってバグを直した経験があります。そこまで野蛮な方法を取らなくても、sshで入ってリクエスト叩きながらログを読んだり、プリントデバッグを仕込むなどの手段を使って、とにかくなんとか直す手段を持っていました。

しかし、コンテナでsshを封じられ、サーバレス環境ではさらに古来からのデバッグ手段を縛られる始末。

例えば、本番で特定のパラメータを入れたときだけ発生するバグは、あらかじめログを詳細に残しておかないと再現することすらままなりません。あと、サーバレスでお手軽にリクエスト単位で見れるログをどうやって吐くの?って問題もありますね。というのをAWS X-Rayを使って解決してみました。

新マスタデータ管理システムakashic

LambdaとX-Rayを組み合わせてみたのは、ゲームを作るための内製システムakashicです。

techblog.kayac.com

Lambda上のakashicのアプリケーションの特性としては、

  • Go言語のLambda関数をALBでInvokeしている
  • 1時間あたりのAPIリクエストが50回から100回程度。使われるのも営業時間中の4時間程度
  • 1回の関数あたりの実行時間は10秒〜60秒
    • Google Sheets APIの待ち時間が多くを占める
  • Lambdaが起動するAPIは、Google Sheetsのメニューに埋め込んだGoogle App Scriptか、akashic-clientというCLIコマンドから呼び出される

f:id:mackee_w:20191223174820p:plain
akashicのGASからの呼び出しメニュー

と言った感じです。業務に必要な内製ツールではよくあるようなワークロードではないでしょうか。

内製ツールの運用負荷というのを下げるという意味でも、akashicをAWS Lambdaで動かしています。複数人が同時に使っているときなどには、勝手にスケールアウトしますし、永続化層をakashicが持っていないため、Lambdaに適したアプリケーションであると言えます。

実際にこの構成で大体のケースではちゃんと動くのですが、スプレッドシートという自由な入力データを扱い特性から、使用している方からしばしば意図通りに動かないという問い合わせがありました。

よく多い、ちゃんと動かないという問い合わせとしては、

  • APIの実行時間がタイムアウトしたという表示(GAS)
  • 特定のシートを読み込んだときだけエラーが出る

などがあります。一個ずつ見ていきます。

「APIの実行時間がタイムアウトした」

akashicのGoogle Sheets統合の仕組みは、シート上のメニューからGoogle App Scriptの関数を実行し、関数の中でシートのキー名や各種オプションを読み取った上で、ALBにぶら下がっているLambdaにリクエストを投げているという仕組みです。

最初の方では別に問題がなかったのですが、開発が進んで取り込むマスタデータの量が多くなってきたところで、が「APIがタイムアウトしました」というエラーがGASのほうで出てきたようです。

早速Lambdaの実行時間を、ログを見て調べてみました。すると、リクエストを受けてからレスポンスを返しきるまで61秒から59秒ほどかかっていましたが、Lambda上では元気に200を返した気になっているログが出ています。

ここで、「はは〜ん、GAS側に1分でなにかが起こる制限があるんだな〜」と思って、GASのドキュメントを調べてみます。

Quotas for Google Services

GASユーザはよくご存知の通り、GASの実行時間には6分という制限があります。

Script runtime 6 min / execution

ですが、URL Fetchの項目を見てもリクエストやレスポンスのサイズに関する制限があるだけで、「1分的なもの」はありません。

うーむ、と思いましたが、とりあえず余裕を見て50秒ぐらいに納めればだいたいタイム・アウトしなくなるのはわかってたので高速化していきます。

「推測するな、計測せよ」

見出しの言葉の通り、何が時間を食っているのか(いや、推測はできていたのですが)知らないふりをして、計測する手段を導入します。

Lambdaで時間がかかるといえば何個かパターンがあります。

これを可視化するために使ったのが、分散トレーシングサービスのAWS X-Rayです。本来は、多数のマイクロサービスを束ねたようなサービスを一気通貫でログを見たり、リクエストの経路を追いかける目的のサービスですが、外部APIを多く叩くような場合でも有用です。

幸いなことにAWS LambdaはX-Rayとネイティブに連携出来るため、ECSなどで使うときのような別途デーモンを立てたりするような手間ありません。

https://docs.aws.amazon.com/ja_jp/lambda/latest/dg/lambda-x-ray.html

また、Goなので、X-Ray SDK for Goを使えば、だいたい事足ります......。いやそんな簡単なものではなかった。

Webサービスならまだしも、多くのフィルタやアウトプットする君を入れ替えられるakashicの設計では、一部のコンポーネントにうまくcontextが伝搬していないケースがありました。なので、そこそこの書き換えが発生しました。

別のサービスで、同じようなことを倍ぐらいやった、同僚のれもんさんの資料があるので、これを見てください。

開発期間数年のサービスの完成間際にcontext対応をぶち込む / introduce context.Context into long term project - Speaker Deck

なにはともあれ、akashicにX-Rayを導入できました。すると、このような感じでいい感じに...

f:id:mackee_w:20191223174943p:plain
直列にSheets APIリクエストが連なっている...

oh...。やはりGoogle Sheets APIのレスポンス待ちで時間がかかっているようです。Google Sheets APIはデカいシートを一気にAPIで取ってこようとすると、Google側でタイムアウトしたり、何分も時間が掛かるケースがあったため、このように1つのファイルでも複数回にAPIリクエストを分割して取ってくる仕組みになっています。

どうやらここを並列化すれば良さそうですね。goroutineとchannelでちょちょちょいっと。

f:id:mackee_w:20191223175013p:plain
APIリクエストを並列化した結果

このとおりきれいに並列リクエスト化できましたね。ただ、API Quotaなどでn分間あたりのリクエスト数が決まっているので無闇矢鱈に並列化するのはやめましょう。ちなみに、Sheets API v4の場合は、1プロジェクトあたり100秒間で500リクエスト、1ユーザあたり100秒間で100リクエストという制限があります。注意しましょう。

Usage Limits  |  Sheets API  |  Google Developers

これで50秒以内にだいたい処理が終わるようになったため、タイムアウトが発生することはなくなりました。しかし、並列リクエストなどのチューニングを駆使しても1分を超えることはあるかと思います。そのときはStep FunctionsでLambdaを起動する形に改めようかと思っています。

「特定のシートを読み込んだときだけエラーが出る」

上記の話を見て、だいたいバグだったり入力側でどうにか出来る話が多いのですが、ここで困るのは再現手順です。そこで、以下のようにX-RayのAnnotationとして、リクエスト時のパラメータを埋め込んでみました。

xray.AddAnnotation(ctx, "SchemaRef", exportReq.SchemaRef)
xray.AddAnnotation(ctx, "Tag", exportReq.Tag)

するとこのような感じでリクエストごとのパラメータが、トレース結果内に埋め込まれます。

f:id:mackee_w:20191223175100p:plain

また、お問い合わせIDとして、X-Rayのtrace_idを表示すると、エラーが出たといわれたときに「お問い合わせIDはなんですか」と聞くだけで、どういう状況でエラーが起こったかがわかります。

f:id:mackee_w:20191223175115p:plain

エラーログもtrace_idに紐付いているので、わざわざ同じ状況を確認しなくても、ログからエラー内容を確認することも出来るようになりました。

X-Rayのデメリット

カヤックでは内製システム以外でも、ユーザにレスポンスを返している部分でX-Rayを組み込んでいます。ですが、全てのリクエストに対してログをサンプリングしていると、お金がかかってしまいます。

料金- AWS X-Ray | AWS

なので、一般的には5%や1%程度のリクエストをサンプリングしてトレース記録を行ったり、例外が起こったときのみトレースログを送信するなどの工夫をしています。

ですが、内製システムのような場合ですとリクエスト数もたかが知れているので、全件トレースされてもそこまで料金に影響がありません。実質便利になるだけです。

もう一つのデメリットとして、ローカルで動かす際に、X-Rayデーモンがいないと言われて、エラーログが大量に出る場合があります。それに関しては、以下のようなemitterを噛まして、出力を抑制しています。

    ss, _ := sampling.NewLocalizedStrategyFromJSONBytes(
        []byte(`{ "version": 2, "default": { "rate": 0 } }`),
    )

    xray.Configure(xray.Config{
        SamplingStrategy:       ss,
        ContextMissingStrategy: ctxmissing.NewDefaultLogErrorStrategy(),
        LogLevel:               "error",
        Emitter:                &DiscardEmitter{},
    })
// DiscardEmitter は どこにもログを送信しないemitterです
type DiscardEmitter struct{}

// Emit は本来XRayデーモンに送るメソッドですが何もしません
func (d *DiscardEmitter) Emit(seg *xray.Segment) {}

// RefreshEmitterWithAddress は本来XRayデーモンのアドレスを設定しますが何もしません
func (d *DiscardEmitter) RefreshEmitterWithAddress(raddr *net.UDPAddr) {}

まとめ

  • Lambdaでサーバレスアプリケーションを作る時に、デバッグやトラブルシューティング目的でX-Ray組み込むと便利という話をしました
    • SAM Localを使ってデバッグするという別の方向性もあるかとは思います
    • ですが、Google Sheets APIと組み合わせて使用する以上、実際にデータ出ないと出ない不具合を解決するためにX-Rayが便利でした
  • 内製ツールをLambdaで作っておくと、ほぼ手放し運用ができますし、コストもかからないのでぴったりなユースケースです

WEB+DB Press Vol.114 に「マネージドサービスによる既存サーバの再構築」を寄稿しました

SREチームの藤原です。Tech Kayac Advent Calendar Migration Track 24日目の記事です。

昨日12/23に発売となった技術評論社さんの WEB+DB Press vol.114 の連載「インフラ運用のアイデア&テクニック」に、「マネージドサービスによる既存サーバの再構築」という記事を書きました。

この記事は builderscon tokyo 2019 の発表 レガシーサーバーを現代の技術で再構築する/builderscon2019 - Speaker Deck を元にして再構築したものです。発表後のフィードバックアンケートで「書籍化してほしい」という声があったので、文章にまとめておくのもいいかなということで転成させました。是非お買い求めください。

5年前に EC2 シングル構成で立てたホストに Redmine, Subversion 他便利なサーバ機能が寄せ集まっている開発支援サーバーを、必要な機能を分解しコンテナに移行する。URL を変えずに Amazon ECS 上に徐々に機能を移動させて、最終的には EC2 をなくすところまでリプレースする、という事例を元に、具体的な設計、手順、移行作業を行った記録をまとめたものです。

8月の builderscon での発表時点では、実際には未完 (部分的に移行していた) だったのですが、その後も作業を進めた結果、先日12月中旬に無事にすべて移行が終わり、約5年稼働した EC2 インスタンスと EBS が削除されました。だいぶ時間がかかったのは特に想定外の事象があったからではなく、単に自分が別プロジェクトに関わっていて作業が進まなかったからで、最終的にも発表時点の計画通りの構成で落ち着いています。年内に片が付いてよかったですね。

f:id:sfujiwara:20191223122040p:plain

移行後のコストは、2.5TB程度あった EBS の大部分が EFS の低頻度アクセスストレージになり大幅減、コンピューティングコストは Fargate Spot のリリースもあって移行前と同程度以下に抑えられる見込みのため、トータルではだいぶ固定費が下がって嬉しい結果となりました。

ということで、個人的には今年の一大プロジェクトが無事に終わって、いい気持ちで年を越せそうです。皆様もよいお年をお迎えください!