[GCP] [標準logライブラリ]構造化ログにX-Cloud-Trace-ContextのtraceIdをセットする
- 本記事について
- GCPにおけるTraceId
- GolangでのX-Cloud-Trace-Contextの取得方法
- DDDレイヤーの各層でログを出力する
- 実装内容
- Cloud Loggingで改善したログをみてみる
- githubにコードあるのでよかったらご参照ください。
- 参考
本記事について
下記記事で、Cloud Runで動くアプリのログを Cloud Loggingで管理できるように 標準logライブラリを使った構造化ログの実装をしました。
ただLogEntryのTraceフィールドにtraceIdを埋めれておらず、運用上必須になるものが足りていないという致命的な問題がありました。
なので本記事では前回の記事のプログラムを改良し、リクエスト毎にユニークなtraceIdを構造化ログに含めて出力できるようにしたいと思います。
LogEntryについては下記を参照ください。
GCPにおけるTraceId
Cloud Runへのアクセスを定める一意のIDについてどうするか、という点についてですが
Cloud Runへのリクエストには
X-Cloud-Trace-ContextというHttp Headerが付与されて届きます。
X-Cloud-Trace-Contextのフォーマット
"X-Cloud-Trace-Context: TRACE_ID/SPAN_ID;o=TRACE_TRUE"
この中のTRACE_IDは公式(https://cloud.google.com/trace/docs/setup#force-trace)にも記載がある通りユニークな文字列となっております。
TRACE_ID は、128 ビットの番号を表す 32 文字の 16 進数値です。 リクエストを束ねるつもりがないのであれば、リクエスト間で一意の値にする必要があります。これには UUID を使用できます。
GolangでのX-Cloud-Trace-Contextの取得方法
net/httpを使用した実装の場合と限定してしまいますが（僕自身のAPIがnet/httpで実装しているため）
X-Cloud-Trace-Contextはhttp headerなので下記のように取得します。
traceHeader := r.Header.Get("X-Cloud-Trace-Context")
今回欲しいのは/で区切った一つ目のTRACE_IDに当たる部分のため、下記のようにして取り出します。
import ( "net/http" "strings" ) // X-Cloud-Trace-Context ヘッダーからTRACE_IDを取り出すメソッド func GetTraceId(r *http.Request) string { traceHeader := r.Header.Get("X-Cloud-Trace-Context") traceParts := strings.Split(traceHeader, "/") traceId := "" if len(traceParts) > 0 { traceId = traceParts[0] } return traceId }
https://github.com/MoriTomo7315/go-user-rest-api/blob/master/gcplogger/log_entry.go#L74-L82
DDDレイヤーの各層でログを出力する
実装前の状況
controller層、application層、infrastructure層のどの層であっても、 何の処理か、どこでエラーが起きたかをログとして出力したいです。
ただ前回までの記事における私のアプリのバージョンは下図のような構成になっており、
controller層、application層ではr *http.Requestを使用するのでtraceIdを取り出せますが、
infrastructure層ではr *http.Requestを受け取っていないのでtraceIdを取得できません。
contextを使用してtraceIdをinfrastructure層へ伝搬
infrastructure層にもhttp.Requestを渡せばいいかと思いましたが、
traceIdを取得するためだけにhttp.Requestをinfrastructure層に伝搬するのは、なんかやりすぎ感があるので避けたかったです。
そこでcontextを使用して解決することにしました。
context packageのドキュメント(https://pkg.go.dev/context)に記載があるように、
1リクエストに対して1つのcontextが生成されます。APIの境界やプロセス間(Gorutineなどの並行処理？）を超えてキャンセル信号や処理の締め切りなどを伝搬するために使用します。
Package context defines the Context type, which carries deadlines, cancellation signals, and other request-scoped values across API boundaries and between processes.
APIの境界を越えてというのがあまりパッとしないかもしれませんが、
firestore clientを生成する際にもrequestごとにcontextを生成して下記のように初期化する必要があります。
なので本アプリでもfirestoreとの接続開始時にcontext.Backgroud()を用いてcontextを作成しfirestore clientに渡す処理をしていました。
// .envのGOOGLE_APPLICATION_CREDENTIALSに設定されているJSONファイルから認証情報を暗黙的に読み取る app, err := firebase.NewApp(ctx, nil)
またcontextは値をセットすることも可能です。
これが本記事の解決ポイントでした。
// keyは文字列、valueはセットしたい値で型はinterface{} ctx := context.WithValue(context.Background(), "key", value)
なのでinfrastructure層で毎回contextを生成するのであれば、
application層でcontextを生成し、traceIdをcontextにセットしてinfrastructure層に伝播する。
そしてinfrastructure層は受け取ったcontextを
- 既存通りfirestore client生成のためにcontextを使用
- contextからtraceIdを受け取ってログを出力
で使用しちゃえば解決になりそうです、
contextの正しい使い方かはちょっと自信がないですが。
図内のlogger.GetTraceId(r)については次節で実装しています。
実装内容
ログを出力するためのコード実装
本コードは構造化ログのためにseverity, message, traceのJSONを作成するための構造体とログ出力に関わるメソッドを書いています。
infrastructure層にこのソースコードを置くか迷いましたが、
各層全てにまたがって使用されるためpackageとして利用する方がいいだろうということで、
とりあえずproject root直下に作成しました。
https://github.com/MoriTomo7315/go-user-rest-api/blob/master/gcplogger/log_entry.go
package gcplogger import ( "encoding/json" "log" "net/http" "strings" ) // ログレベルのCONSTを定義 // https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#logseverity var ( INFO = "INFO" WARN = "WARNING" ERROR = "ERROR" ) // GCPのLogEntryに則った構造化ログモデル type LogEntry struct { // GCP上でLogLevelを表す Severity string `json:"severity"` // ログの内容 Message string `json:"message"` // トレースID Trace string `json:"trace"` } // 構造体をJSON形式の文字列へ変換 // 参考: https://cloud.google.com/run/docs/logging#run_manual_logging-go func (l LogEntry) String() string { if l.Severity == "" { l.Severity = INFO } out, err := json.Marshal(l) if err != nil { log.Printf("json.Marshal: %v", err) } return string(out) } // INFOレベルのログ出力 func InfoLogEntry(message string, trace string) string { entry := &LogEntry{ Severity: INFO, Message: message, Trace: trace, } return entry.String() } // WARNレベルのログ出力 func WarnLogEntry(message string, trace string) string { entry := &LogEntry{ Severity: WARN, Message: message, Trace: trace, } return entry.String() } // ERRORレベルのログ出力 func ErrorLogEntry(message string, trace string) string { entry := &LogEntry{ Severity: ERROR, Message: message, Trace: trace, } return entry.String() } // http "X-Cloud-Trace-Context" headerからtraceIdを抜き出す func GetTraceId(r *http.Request) string { traceHeader := r.Header.Get("X-Cloud-Trace-Context") traceParts := strings.Split(traceHeader, "/") traceId := "" if len(traceParts) > 0 { traceId = traceParts[0] } return traceId }
controller層からの呼び出し
コードは省略しているので本記事以外の内容で説明が不足しているところはgithubを参照ください(ページ最後にURL記載)。
package controller import ( "log" "net/http" "strings" "github.com/MoriTomo7315/go-user-rest-api/application" logger "github.com/MoriTomo7315/go-user-rest-api/gcplogger" ) type UserController interface { HandlerHttpRequest(w http.ResponseWriter, r *http.Request) } type userController struct { userApplication application.UserApplication } func NewUserController(ua application.UserApplication) UserController { return &userController{ userApplication: ua, } } func (uc *userController) HandlerHttpRequest(w http.ResponseWriter, r *http.Request) { // traceIdを取得 traceId := logger.GetTraceId(r) // messageとtraceIdをセットして構造化ログを出力 log.Printf(logger.InfoLogEntry("[/api/users] START ===========", traceId)) case http.MethodGet: /* 全Userを取得する */ uc.userApplication.GetUsers(w, r) ... } log.Printf(logger.InfoLogEntry("[/api/users] END ===========", traceId)) }
application層からの呼び出し
コードは省略しているので本記事以外の内容で説明が不足しているところはgithubを参照ください(ページ最後にURL記載)。
package application import ( // go1.7の場合, それ以前の場合は"golang.org/x/net/context"らしい "context" "log" "net/http" "github.com/MoriTomo7315/go-user-rest-api/application/util" "github.com/MoriTomo7315/go-user-rest-api/domain/repository" logger "github.com/MoriTomo7315/go-user-rest-api/gcplogger" ) // インターフェース type UserApplication interface { GetUsers(w http.ResponseWriter, r *http.Request) ... } type userApplication struct { firestoreRepository repository.FirestoreRepository } // Userデータに関するUseCaseを生成 func NewUserApplication(fr repository.FirestoreRepository) UserApplication { return &userApplication{ firestoreRepository: fr, } } // ユーザ一覧取得 func (ua userApplication) GetUsers(w http.ResponseWriter, r *http.Request) { // traceIdをhttp headerから取得 traceId := logger.GetTraceId(r) // contextを作成しtraceIdをセットする ctx := context.WithValue(context.Background(), "traceId", traceId) // ログ出力 log.Printf(logger.InfoLogEntry("[GetUsers] Application logic start", traceId)) // firestoreからユーザ情報を取得するためにinfrastructure層のメソッドを呼びだし(traceIdをセットしてcontextをセット) users, err := ua.firestoreRepository.GetUsers(ctx) if err != nil { util.CreateErrorResponse(w, ctx, err, "") return } resModel := util.GetResponse(http.StatusOK, "ユーザ情報取得に成功しました。", int64(len(users)), users) res, _ := json.Marshal(resModel) w.Header().Set("Content-Type", "application/json") w.Write(res) }
infrastructure層からの呼び出し
package persistence import ( "fmt" "log" "context" firestore "cloud.google.com/go/firestore" firebase "firebase.google.com/go/v4" "github.com/MoriTomo7315/go-user-rest-api/domain/model" "github.com/MoriTomo7315/go-user-rest-api/domain/repository" logger "github.com/MoriTomo7315/go-user-rest-api/gcplogger" "google.golang.org/api/iterator" ) type firestoreClient struct{} func NewFirestoreClient() repository.FirestoreRepository { return &firestoreClient{} } func initFireStoreClient(ctx context.Context) (*firestore.Client, error) { // contextからtraceIdを取得 // contextにセットした値はinterface{}型のため.(string)でassertionが必要 traceId := ctx.Value("traceId").(string) // .envのGOOGLE_APPLICATION_CREDENTIALSから暗黙的に設定を読み取る app, err := firebase.NewApp(ctx, nil) if err != nil { log.Printf(logger.ErrorLogEntry(fmt.Sprintf("firebase.NewAppに失敗 %v", err), traceId)) return nil, err } client, err := app.Firestore(ctx) if err != nil { log.Printf(logger.ErrorLogEntry(fmt.Sprintf("firestore client 初期化に失敗 %s", err), traceId)) return nil, err } return client, nil } // firestoreから全ユーザの情報を取得する func (f *firestoreClient) GetUsers(ctx context.Context) (users []*model.User, err error) { // contextからtraceIdを取得 // contextにセットした値はinterface{}型のため.(string)でassertionが必要 traceId := ctx.Value("traceId").(string) log.Printf(logger.InfoLogEntry("[GetUsers] connecting firestore start.", traceId)) client, err := initFireStoreClient(ctx) defer client.Close() if err != nil { log.Printf(logger.ErrorLogEntry(fmt.Sprintf("firestore clientの初期化に失敗 err=%v", err), traceId)) return nil, define.SYSTEM_ERR } iter := client.Collection("users").Documents(ctx) for { userDocSnap, err := iter.Next() if err == iterator.Done { break } if err != nil { log.Printf(logger.ErrorLogEntry(fmt.Sprintf("firestoreからusersコレクションの検索に失敗 err=%v", err), traceId)) return nil, define.NOT_FOUND_USER } // Uidをmap[string]interface{}に含める userData := userDocSnap.Data() userData["id"] = userDocSnap.Ref.ID // map[string]interface{} →json []byte -> *model.BookingModel jsonuserData, _ := json.Marshal(userData) var user *model.User json.Unmarshal(jsonuserData, &user) users = append(users, user) } log.Printf(logger.InfoLogEntry("[GetUsers] connecting firestore end.", traceId)) return users, nil }
Cloud Loggingで改善したログをみてみる
実際にcloud runにデプロイして2回リクエストを送ってみました。
1回目(正常ケース)
trace: 8574ebc0f0e8bc59a74c1d44f9b6ca60 がはいっています。
2回目(エラーケース)
こちらもtrace: ef47f74c450cdd28e24a5cad7fa7bb56 がはいってます。
エラーケースのログだけフィルタできるか試す
Cloud Loggingの機能でtrace: ef47f74c450cdd28e24a5cad7fa7bb56でフィルタリングして、エラー時のプロセスだけ絞ることもできました。
下記クエリでフィルタリング。
resource.type = "cloud_run_revision" resource.labels.service_name = "go-rest-user-api" resource.labels.location = "xxxxxxxxxx" severity>=INFO jsonPayload.trace="ef47f74c450cdd28e24a5cad7fa7bb56"
期待通り対象のプロセスのログだけフィルタリング可能。
githubにコードあるのでよかったらご参照ください。
参考
https://cloud.google.com/run/docs/logging#writing_structured_logs
