CloudRun で GAE のログを再現する

GAE のログといえば、リクエストに紐づいたログ出力ができることが魅力の一つですが、今回これを CloudRun で再現しました！！

リクエストに紐づくヘッダー

GCP には GAE というコンピューティングプラットフォームがありますが、魅力的なものとして、フルマネージドな環境であることに加えて リクエストにログを関連付ける ことができることがあります。

ただ、これは GAE 特有の機能であり、他のコンピューティングプラットフォームではできません。

GAEのログは魅力的で GAE のログに憧れてというブログを執筆されている方がいらっしゃるぐらいです。

上記のブログでは GKE で解決するためのライブラリを作成しています。

https://github.com/yfuruyama/stackdriver-request-context-log

また、そのブログでは 6 つの条件を満たす必要があることが書かれていて、かなり複雑に思えます。

しかし、GCP のフルマネージド環境を利用している場合、やることは比較的シンプルになります。詳細については後述していきます。

どうやってリクエストにログを紐づければ良いのか

GAE のアプリケーションログのドキュメントを読んでみます。

アプリログのエントリをリクエストログに関連付ける場合は、構造化アプリログのエントリにリクエストのトレース ID を含める必要があります。X-Cloud-Trace-Context リクエストヘッダーからトレース ID を抽出できます。構造化ログエントリで、ID を logging.googleapis.com/trace という名前のフィールドに書き込みます。

参照: https://cloud.google.com/appengine/docs/standard/go/writing-application-logs#writing_app_logs

構造化アプリログのエントリにリクエストのトレース ID を含める 必要があるそうです。

そして、それをするには、X-Cloud-Trace-Context の構造 を知る必要がありそうです。X-Cloud-Trace-Context からトレース ID を抽出すれば良いわけなので。

これについては、 GCP Cloud Trace に記述されています。

TRACE_ID は、128 ビットの番号を表す 32 文字の 16 進数値です。リクエストを束ねるつもりがないのであれば、リクエスト間で一意の値にする必要があります。これには UUID を使用できます。
SPAN_ID は（符号なしの）スパン ID の 10 進数表現です。トレースの最初のスパンでは 0 に設定します。後続のリクエストでは、SPAN_ID を親リクエストのスパン ID に設定します。ネストされたトレースの詳細については、TraceSpan（REST、RPC）の説明をご覧ください。
このリクエストをトレースするには、TRACE_TRUE を 1 に設定する必要があります。リクエストをトレースしない場合は 0 を指定します。

参照: https://cloud.google.com/trace/docs/setup#force-trace

X-Cloud-Trace-Context の定義は以下です。

X-Cloud-Trace-Context: TRACE_ID/SPAN_ID;o=TRACE_TRUE

gin を利用している場合は、 gin.Context.GetHeader("X-Cloud-Trace-Context") によって抽出できます。GCP のフルマネージドなプラットフォームを利用している場合は、ロードバランサによってヘッダーが登録されています (https://cloud.google.com/load-balancing/docs/https?hl=ja#target-proxies)

ちなみに、以下のような値を取得できます。

c09201be6a289095b5e4035b0ab7f9f8/16156841576706601771

この場合、以下のような値になります。

TRACE_ID : c09201be6a289095b5e4035b0ab7f9f8
SPAN_ID  : 16156841576706601771

ここまで理解したら、あとは 構造化アプリログのエントリにリクエストのトレース ID を含める を達成すれば良いのです。

zerolog で実装する

以前執筆したブログで、構造化ログのパッケージについてはまとめています。(https://onemuri.space/note/4xhm6jmts)

この中でも、 rs/zerolog を今回は利用します。

パッケージの追加

また web framework として、 gin を利用します。

go get -u github.com/gin-gonic/gin
go get -u github.com/rs/zerolog/log

サンプルコード

func main() {
    router := gin.New()
    router.Use(func(c *gin.Context) {
        logger.SetLogger(c)
    })
    r.GET("/test", func(c *gin.Context) {
		logger.Info().Msg("info log")
		c.JSON(http.StatusOK, nil)
	})
    router.Run()
}

logger のパッケージを適当に切って以下のコードをコピペしてください。パッケージ名は好きな名前で良いです。そのときは都度コードを修正してください。

var logger = log{}

type log struct {
	ctx zerolog.Context
}
func SetLogger(c *gin.Context) {
	ctx := zerolog.New(os.Stdout).With()
	traceHeader := c.GetHeader("X-Cloud-Trace-Context")
	traceID, _ := parseTraceFromHeader(traceHeader)
	if traceID == "" {
		logger.ctx = ctx
		return
	}
	projectID := os.Getenv("GOOGLE_PROJECT_ID")
	if projectID == "" {
		logger.ctx = ctx
		return
	}
	trace := fmt.Sprintf("projects/%s/traces/%s", projectID, traceID)
	logger.ctx = ctx.Str("logging.googleapis.com/trace", trace)
}
func parseTraceFromHeader(header string) (traceID, spanID string) {
    // パース処理
	return traceID, spanID
}
func Info() *zerolog.Event {
	log := logger.ctx.Str("severity", "info").Logger()
	return log.Info()
}

パース処理部分はお任せします。この状態でサーバーを起動して、以下のリクエストを叩いてみてください。

curl -H 'X-Cloud-Trace-Context:c09201be6a289095b5e4035b0ab7f9f8/16156841576706601771' localhost:8080/test

zerolog は json 形式でログを吐き出します。以下のようなログが出力されていれば大丈夫です。

{
  "level": "info",
  "logging.googleapis.com/trace": "projects/your-project-id/traces/c09201be6a289095b5e4035b0ab7f9f8",
  "severity": "info",
  "message": "info log"
}

logging.googleapis.com/trace がリクエストログと同じ traceID になっていることが重要です。

Stackdriver Logging にて確認 & 解説

先ほどの処理を実装した api をデプロイして確認した結果が以下です。(エンドポイントは少し変えてます)

trace リクエストに設定されていて、ログの trace を自作した同じ trace をログのエントリに含めるようにしています。

サンプルコードの ctx.Str() メソッドの部分です。(ctx は zerolog.Context である点に注意)

trace := fmt.Sprintf("projects/%s/traces/%s", projectID, traceID)
logger.ctx = ctx.Str("logging.googleapis.com/trace", trace)

logging.googleapis.com/trace のフィールドを持ったログを出力すれば良いのです。

以下の部分ですね。(severity を設定しないと Logging 上で serverity なしとして処理してしまうので注意です。)

func Info() *zerolog.Event {
	log := logger.ctx.Str("severity", "info").Logger()
	return log.Info()
}

logger.Info().Msg("info log")

まとめ

X-Cloud-Trace-Context ヘッダーから TraceID を抽出してリクエストにログを関連づけてみました。まだまだ、参考記事がほとんどない状態なので、誰かの参考になると幸いです。