AWS X-Ray Go SDK の地雷処理をしている話

AWS Lambda Perl Runtime で AWS X-Ray を使えるようになりましたで紹介した AWSの分散アプリケーションの分析サービス AWS X-Ray。 Perl から使えるようにしたももの、自分自身は最近 Perl をあまり使っていないことに気がついた！！ので、AWSが提供しているGo実装である aws/aws-xray-sdk-goに手を出してみることにしました。

結果、X-Rayのサービスマップやトーレスが見れるようになって便利！・・・にはなったんですが、そこまでの道のりが長かった。「 @fujiwara さんのYAPC::Tokyo 2019での発表から1年近く経ってるしそろそろ安定してきているでしょ！」と軽い気持ちで始めたのが良くない。色々と地雷(？)を踏んだので、記録として残しておきます。

依存ライブラリのcontext対応が地味に辛い

X-Ray で実行をトレースするには、「今実行している関数がどこから呼ばれたのか？」という情報をうまいこと伝える必要があります。 Perlで使われているような黒魔術はGoでは使えないので、 context.Context を地道に引数に渡していくことになります。

まあ、こんなこともあろうかと、context.Context にはバッチリ対応してあるからサクッと行けるでしょ！

と思ってたんですが、現実はそうは甘くなかった。 X-Rayを入れようとしたプロジェクトではWebフレームワークとしてgoadesign/goaを使っています。 GoaのHTTPハンドラーには context.Context が渡ってくるので油断していたのですが、 contextの親をたどっていくと行き着く先は context.Background() (HTTPハンドラーなので request.Context() であってほしい)。なんとなく context.Context 対応詐欺にあった気分です。

Goaは現在 v2, v3 の開発がメインで現在使っているのは v1 です。 v1からv3へのアップグレードには大幅な書き換えが必要なこと、アップグレードしたとしても直っている保証がないこと、最近 Goa v1 のリリースが滞りがちなこと、などなどの理由から結局フォークしてくることにしました。

shogo82148/goa-v1

AWS X-Ray Go SDK 自体の問題ではないのですが、 Contextってタイムアウトをうまく処理するための仕組みなので、実装漏れがちですよね。皆さん実装するときやライブラリの選定には気をつけましょう。

SQLクエリを実行する関数のシグネチャーが微妙に違う

これに関しては @acidlemon 先生の kamakura.go の資料を見るのが手っ取り早いです。

開発期間数年のサービスの完成間際にcontext対応をぶち込む / introduce context.Context into long term project kamakura.go #5 @ 鎌倉

*sql.DB のクエリ実行関数のシグネチャーは func QueryContext(ctx context.Context, query string, args ...interface{}) (*Rows, error) なのに対して、 *xray.DB のシグネチャーは func Query(ctx context.Context, query string, args ...interface{}) (*Rows, error)。せめてシグネチャーだけ合わせておいてくれればインターフェースで回避できたものの名前が微妙に違う。最初から X-Ray 前提でコードを書くか、インターフェースを適合させるためのアダプターが必要になります。

これに関しては一旦トレースを諦めて、SDKにプルリクエストを送って対応してもらうのを待つことにしました。

proposal: implement custom driver for xray instead of xray.DB #169

go-sql-proxyがcontextに対応しましたと同じアプローチでトレースコードを差し込む実装です。まだマージされていないですが、「方針は良さそう！」みたいなコメントをもらえたので、マージされるといいな。これが入るとSQLドライバーを変更するだけでOKなので、既存のコードの変更はほとんどなくなります。

2020-03-30追記: ↑のプルリクエスト、無事マージしてもらえました。v1.0.0-rc.15 移行で使えます。

デフォルトで落ちてくるバージョンが古い

ここまでの地雷は目に見えてわかる(ドキュメントに書いてあるし、なにか問題があればコンパイルエラーになる)ので簡単でしたね。 ここからは目に見えなくて地味につらいやつです。

READMEに書いてあるとおりに go get github.com/aws/aws-xray-sdk-go してくると落ちてくるバージョンは v0.9.4 です。しかしこのリリースは 2017年9月 のもの。2年も前のバージョンです。

最新リリースは v1.0.0-rc.14 (2019年9月)です。しかし、 go get はデフォルトではRC版をとってきてくれません。明示的に go get github.com/aws/aws-xray-sdk-go@v1.0.0-rc.14 を指定する必要があります。バグフィックスが多めなのと、カジュアルに新機能とかが入ってくるので、RC版の使用を強く推奨します。

contextを正しく扱ってないときはデフォルトpanic

X-Ray はアプリケーションの処理の単位をセグメントをいう概念で表します。

AWS X-Ray の概念

処理が複数に分割できる場合、セグメントが複数のサブセグメント含む場合があります。ここで注意が必要なのは、セグメントの作成とサブセグメントの作成との挙動の違いです。

サブセグメントを作るときは 親になるセグメントが必須 です。

// 親セグメントが見つからないので panic
ctx, seg := xray.BeginSubsegment(context.Background(), "subsegment-name")

// サブセグメントを作るにはセグメントが必要
ctx, seg := xray.BeginSegment(context.Background(), "service-name")
ctx, subseg := xray.BeginSubsegment(ctx, "subsegment-name")

セグメント同士には親子関係を設定できません。例えば以下のコードで seg1 と seg2 は無関係な別のセグメントです。

// seg1 と seg2 は関連のない別のセグメントとして扱われる
ctx, seg1 := xray.BeginSegment(context.Background(), "service-name")
ctx, seg2 := xray.BeginSegment(ctx, "subsegment-name")

SDKにはいくつかユーティリティ関数が用意されていますが、こういった理由から作成するのがセグメントなのかサブセグメントなのかが重要です。 xray.Handler はセグメントを、 xray.Capture, xray.AWS, xray.Client, xray.SQL はサブセグメントを作成します。サブセグメントを作るユーティリティ関数を使うときは、必ず親セグメントが存在しなければなりません。

ここで問題になってくるのが 親セグメントが設定されていない場合はデフォルトでpanicする ということです。もちろん、この動作は変更可能で、 AWS_XRAY_CONTEXT_MISSING 環境変数でログを吐くだけにできます。

export AWS_XRAY_CONTEXT_MISSING=LOG_ERROR
# default: RUNTIME_ERROR

うっかり context.Background() なんかを使って AWS API を叩く箇所があると、容赦なく panic します。 panic するとスタックトレースが表示されるのでデバッグには便利ですが、未設定のまま本番環境にあげないようにしましょう。

うっかりをよくやってしまうのでデフォルト LOG_ERROR が良かった・・・。

(ちなみに、この AWS_XRAY_CONTEXT_MISSING 環境変数は、2020-02-11現在の公式ドキュメントには存在しないという地味な落とし穴もあります)

AWS Lambda では LOG_ERROR がデフォルト

さて、前節で出てきた AWS_XRAY_CONTEXT_MISSING ですが、AWS Lambda ではデフォルト値が違います。

環境変数を使用した AWS X-Ray との通信

AWS_XRAY_CONTEXT_MISSING: X-Ray SDK はこの変数を使用して、関数が X-Ray データを記録しようとしたがトレーシングヘッダーを使用できない場合の動作を決定します。Lambda はデフォルトでこの値を LOG_ERROR に設定します

親切ですね。

最初から LOG_ERROR をデフォルトにしてくれると、とてもありがたい・・・。

S3 で大きなファイルをあげようとするとpanicする

Large files cause panic with S3 #175

s3manager を使うと、大きなファイルのアップロード時は自動的に分割してくれます。しかし、分割時に親セグメントの情報を失ってしまうようです。結果、親セグメントが見つからず panic

今の所 panic を避けるには、 AWS_XRAY_CONTEXT_MISSING でログに吐くようにするしか無いようです。

環境変数の設定が常に最優先

AWS_XRAY_CONTEXT_MISSING はアプリケーションからも変更可能です。

xray.Configure(xray.Config{
    ContextMissingStrategy: ctxmissing.LogErrorStrategy,
})

しかし、 環境変数が設定されている場合、この設定は無視されます 。有効になるのは AWS_XRAY_CONTEXT_MISSING が設定されていない場合のみです。

・・・ AWS SDK と真逆ですね？ (例えば AWS_REGION 環境変数よりも、アプリケーション内の config.Region が優先される) なぜ、こんなユーザーを混乱させるような設定になっているんでしょうね？単なる実装ミスかと思い、他言語の X-Ray SDK (Ruby, Python, C#, Java) も確認してみたのですが、 Goと同様に環境変数が最優先でした。

まとめ

AWS X-Ray SDK Go のインストールは以下のコマンドで。

$ go get github.com/aws/aws-xray-sdk-go@v1.0.0-rc.14
$ export AWS_XRAY_CONTEXT_MISSING=LOG_ERROR

main関数の最初の方で、以下の設定をいれること。

xray.Configure(xray.Config{
    ContextMissingStrategy: ctxmissing.LogErrorStrategy,
})

プルリクエスト送るためにザッとSDK全体をみたのですが、 gofmt すらかかっていない状態だったり、グローバル変数を多用していたり、 Goに慣れていない人が別言語の実装を移植した雰囲気があるので、他にも罠がありそうです。

・・・もう書き直して、「俺の考えた最強の AWS X-Ray SDK」を作ったほうが早いんじゃないか？という気もしなくはないですが、これもこみゅにてぃーへの還元・・・もうちょっとだけ頑張って地雷処理してみます・・・。

以下チラシの裏

この辺とか意図がわからなくて困ってる。

	for i := 0; i < len(seg.rawSubsegments); i++ {
		child := seg.rawSubsegments[i]
		seg.rawSubsegments[i] = seg.rawSubsegments[len(seg.rawSubsegments)-1]
		seg.rawSubsegments[len(seg.rawSubsegments)-1] = nil
		seg.rawSubsegments = seg.rawSubsegments[:len(seg.rawSubsegments)-1]

		seg.Subsegments[i] = seg.Subsegments[len(seg.Subsegments)-1]
		seg.Subsegments[len(seg.Subsegments)-1] = nil
		seg.Subsegments = seg.Subsegments[:len(seg.Subsegments)-1]

		atomic.AddUint32(&seg.ParentSegment.totalSubSegments, ^uint32(0))

		// Add extra information into child subsegment
		child.Lock()
		child.beforeEmitSubsegment(seg)
		cb, err:= json.Marshal(child)
		if err!= nil{
			logger.Errorf("JSON error while marshalling subsegment: %v",err)
		}
		outSegments = append(outSegments, cb)
		logger.Debugf("Streaming subsegment named '%s' from segment tree.", child.Name)
		child.Unlock()

		break
	}

~~Go初心者どころか、プログラミング初心者が書いたんじゃないか・・・？~~

Shogo's Blog