GCPで理想の構造化ログを出力する方法

はじめに

この記事では、GCP のマネージドサービス(Google App Engine^[1]/Cloud Run/Cloud Functions/GKE)から Cloud Logging に良い感じの構造化ログ(理想の構造化ログ)を出力する方法について紹介します。

良い感じのログの例

この記事の実装例は Go で書かれていますが Cloud Logging の仕様はどの言語でも同じです。他の言語を使用している方にも十分に参考になる内容になっています。

前提条件

この記事で紹介する構造化ログの実装は基本的に以下の仕様にそって実装しています。重要な仕様なので興味のある方は一度読んでみることをおすすめします。

• 構造化ペイロードの特殊フィールド

用語の解説

本編に入る前に、この記事で使われるログ出力まわりの用語をまとめておきます。以下の用語については前置きなく使いますのでよろしくお願いします。

• 構造化ログ^[2]
  • プレインテキストではなく、JSON等のデータ形式で出力されたログのこと
  • GCPのCloud Logging(旧Stackdriver Logging)ではJSON形式のログは自動的にパースされ、検索クエリで利用することができる
• ログエントリー
  • 構造化ログにおけるログデータのこと
  • 良いログ設計はこのログエントリーの構造をいかに設計するかにかかっていると考えています
• Serverity
  • ログの重大度のこと
  • DefaultからEmergencyまで9種類の重要度が定められている
  • 馴染みのあるのでいうとInfoやError
  • ログエントリーの1フィールドとして設定する
  • 障害検知において重要な情報になる
  • くわしくはこちらを参照のこと
• アクセスログ
  • APIアクセスごとに生成されるログのこと
  • HTTPリクエストだったりgRPCのリクエストだったり
  • リクエストログとも呼ばれる
  • GAEやCloud Runは自動でアクセスログが吐き出される
  • GKEなど自動でアクセスログが吐かれない環境では開発者がMiddlewareやInterceptorに実装しなければならない
• アプリケーションログ
  • 開発者が任意で生成するログのこと
  • 使い方は開発者しだいな面がありサービス特性や運用の用件によりログ設計することが多い
  • 障害検知用にアクセスログではわからない追加情報を吐いたりすることが多い
  • Cloud Loggingではログからメトリクス生成ができるので監視に使ったりすることもある
• ログのグループ化
  • 1つのアクセスログに複数のアプリケーションログを関連付けること
  • アクセスログのことを親ログ、アプリケーションログのことを子ログと表現することがある
  • Cloud LoggingではTraceIDをログデータに含める(その他、細かい条件あり)とログをグループ化することができる

最低限、ログの種類は以下の2種類あるということだけ押さえておいてください。

• アクセスログ
• アプリケーションログ

理想のログ出力とは

まず初めに、理想のログ出力ってなんだろうということについて考えてみたいと思います。超個人的な意見ではありますが、バックエンドAPI開発におけるログ出力で大切なのは以下の4つだと考えています。

1. 障害検知に優れている
2. お問い合わせやバグの調査がしやすい
3. メトリクスが簡単に作成でき監視(モニタリング)に活用できる
4. うっかり個人情報が流れてこない

4番目項目に関しては今回の内容から外れてしまうのでこの記事ではこれ以上言及しませんが、上記項目の1から3を満たすログ出力を GCP の Cloud Logging 向けにどのように実装すれば良いのかみていきましょう。

いい感じのログ出力といえばGAE第1世代ログだった

古くから GCP を使っている人間にとって、いい感じのログ出力といえば Google App Engine(GAE) 第1世代ログです。GAE 第1世代には google.golang.org/appengine/log というライブラリがありこのライブラリを使ってログを出力すると下記画像のようにアクセスログとアプリケーションログを一箇所にグルーピングしてくれます。

GAE 第1世代(Go1.11)は一応まだ Google のサポートが続いている(2020/12現在)ので使おうと思えば使えるのですがサポートが切れるのが時間の問題であり、現在の主流は GAE 第2世代や Cloud Run や GKE なのでいまさら新たに使うことはないと思います。せっかくいい感じのログ出力ができるライブラリがあるのですが、google.golang.org/appengine/log は GAE 第1世代でしか使えなません。

GAE第1世代ログの特徴

GAE 第1世代ログはいい感じのログ出力と書きましたが、それは果たして理想のログ出力なのか考察したいとおもいます。GAE 第1世代ログの特徴は以下です。

• アクセスログ(リクエストログ)にアプリケーションログが関連づけられている
• アプリケーションログは単なるテキストデータ(構造化されていない)
• アプリケーションログはログとして独立していないあくまでアクセスログの子要素である

GAE 第1世代のログが優れているのは理想のログで挙げた項目の1と2(障害検知とバグ調査がしやすい)で、アクセスログからアプリケーションログを辿るだけでいろいろ調査が捗るみたいな部分です。その反面、GAE 第1世代ログは3番目の項目(メトリクス作成が簡単)は苦手です。というのもGAE第1世代ログはアプリケーションログがアクセスログの完全な子要素になっていてログとして独立していません(アクセスログのlineフィールドの中の1要素でしかない)。なのでアプリケーションログの内容を検索してメトリクス作成するときにアクセスログごと検索に引っかかってしまう問題があります。

GAE第1世代ログの良いところを継承しつつ理想のログ出力をするには

GAE 第1世代ログはアクセスログに全て纏まっていてシンプルでわかりやすい反面、アプリケーションログの横串検索がしづらいという弱点があります。そこで GAE 第1世代ログの弱点を補った形でログを出力すると理想のログ出力になりそうです。具体的には以下の特徴を持たせると良さそうです。

• アプリケーションログを一つのログとして独立させる
• アプリケーションログを構造化して出力し、横串での検索やメトリクス作成ができるようにする
• アクセスログにアプリケーションログが関連づけられている

アプリケーションログを一つのログとして独立させる

これは Go の標準ライブラリを使って Stdout にログを出力すればできます。

// Stdoutにログがテキストログが出力される
fmt.Printf("ログの内容")
log.Printf("ログの内容")

ただし上記はログが構造化されておらずプレインテキストとして出力されます。構造化されていないログは CLoud Logging の検索がやりづらいのとアクセスログとアプリケーションログのグルーピングができません。アプリケーションログを独立させると共にログの構造化も実施した方が良いログ出力になります。

アプリケーションログを構造化して出力し、横串での検索やメトリクス作成ができるようにする

Go でログを構造化して出力するには以下のように Stdout または Stderr を指定して JSON を出力すればできます。

type ApplicationLog struct {
    Severity       string         `json:"severity"`
    Message        string         `json:"message"`
    Time           time.Time      `json:"time"`
}
ety := &ApplicationLog{
    Severity:       "INFO",
    Message:        "ログメッセージ",
    Time:           time.Now(),
}
if err := json.NewEncoder(os.Stdout).Encode(ety); err != nil {
    // エラー処理は省略...
}

上記のようにログを出力すればログが独立かつ構造化された形で出力されます。ただしこの状態ではまだアクセスログとアプリケーションログのグルーピングができません。この次でグルーピングについてみていきます。

アクセスログにアプリケーションログが関連づけられている

アクセスログにアプリケーションログを関連づけてグルーピングするには以下の条件を満たす必要があります(GAE のログに憧れてより引用)。

1.parent, child ともに同一 GCP プロジェクトのログであること
2.parent, child で log ID (logName) が別々であること
3.parent, child で Monitored Resource が同一であること (つまりログが吐かれた場所が同じであること)
4.parent に httpRequest.requestUrl が設定されてること (つまり parent は HTTP のアクセスログであること)
5.child のログの時刻が、parent のリクエスト処理内の時刻であること (つまり >child.timestamp >= parent.timestamp — parent.httpRequest.latency && >child.timestamp <= parent.timestamp)
6.trace が同一であること

上記条件にある parent は親ログ、つまりアクセスログのことであり child は子ログ、つまりアプリケーションログのことです。
色々と条件が複雑ですが、GAE と Cloud Run は自動でアクセスログを出力してくれるので最後の条件である「traceが同一であること」を満たせばうまい具合にグルーピングできます。trace は logging.googleapis.com/trace という名前のフィールドに以下の形式で文字列をセットします。

projects/[PROJECT-ID]/traces/[TRACE-ID]

PROJECT-ID には GCP のプロジェクトIDをセットします。TRACE-ID は GAE と Cloud Run のHTTPリクエストヘッダ^[3]に X-Cloud-Trace-Context がセットされているのでそこから TRACE-ID を取得してセットします。X-Cloud-Trace-Context ヘッダは以下のような構造になっています(X-Cloud-Trace-Context ヘッダの仕様についてはこちらを参照してください)。

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

X-Cloud-Trace-Context ヘッダがセットされない環境(素のGKEなど)では OpenTelemetry (旧OpenCensusやOpenTracing)などのトレーシングライブラリを使って TraceID を生成することをおすすめします。

アプリケーションログの実装

ログとして独立していて、かつ構造化されている、かつアクセスログとアプリケーションログがグループ化されるための実装は実際どのようにすれば良いのか、まずはアプリケーションログの実装からみていきましょう。
最低限必要な項目だけで構成されたアプリケーションログの実装は以下のようになります。

type ApplicationLog struct {
    Severity       string         `json:"severity"`
    Message        string         `json:"message"`
    Time           time.Time      `json:"time"`
    Trace          string         `json:"logging.googleapis.com/trace"`
}
func main() {
    ety := &ApplicationLog{
        Severity:       "INFO",
        Message:        "ログメッセージ",
        Time:           time.Now(),
        Trace:          "projects/[PROJECT-ID]/traces/[TRACE-ID]",
    }
    if err := json.NewEncoder(os.Stdout).Encode(ety); err != nil {
        // エラー処理は省略...
    }
}

上記の他にも SpanID や SourceLocation、operation をセットすることができます。詳細はこちらのページを参照してください。

• 構造化ペイロードの特殊フィールド

アクセスログの実装

GAE や Cloud Run では自動でアクセスログが出力されますが、GKE は自前でアクセスログを出力する必要があります。アクセスログを出力するにはアプリケーションログのフィールドに加え HttpRequest フィールドを追加する必要があります。HttpRequest の仕様は以下です。

• HttpRequest
  Go で構造体を定義する場合は以下のようになります。

// アクセスログ
type AccessLog struct {
    Severity    string      `json:"severity"`
    Time        time.Time   `json:"time"`
    Trace       string      `json:"logging.googleapis.com/trace"`
    HTTPRequest HTTPRequest `json:"httpRequest"`
}
// HttpRequest
type HTTPRequest struct {
    RequestMethod string   `json:"requestMethod"`
    RequestURL    string   `json:"requestUrl"`
    RequestSize   string   `json:"requestSize,omitempty"`
    Status        int      `json:"status"`
    ResponseSize  string   `json:"responseSize,omitempty"`
    UserAgent     string   `json:"userAgent,omitempty"`
    RemoteIP      string   `json:"remoteIp,omitempty"`
    ServerIP      string   `json:"serverIp,omitempty"`
    Referer       string   `json:"referer,omitempty"`
    Latency       Duration `json:"latencyy"`
    Protocol      string   `json:"protocol"`
}
type Duration struct {
	Nanos   int32 `json:"nanos"`
	Seconds int64 `json:"seconds"`
}

GKE では Latency に "3.5s" のような文字列をセットすれば問題なかったのですが GAE と Cloud Run では上記のように seconds と nanos をフィールドに持つ構造体にしないと正しくアクセスログとして認識されませんでした。ハマりポイントなので気をつけてください。
Duration 構造体には以下のように time.Duration から構造体の値を生成できる関数を用意しておくと良いと思います。

func MakeDuration(d time.Duration) Duration {
	nanos := d.Nanoseconds()
	secs := nanos / 1e9
	nanos -= secs * 1e9
	return Duration{
		Nanos:   int32(nanos),
		Seconds: secs,
	}
}

アクセスログの時間には何を設定すべきか

アクセスログの Time フィールドにはどの時刻をセットすべきか、これもハマりポイントです。GAE のアクセスログの時刻はアクセスのあった時間が記録されています(ログの先頭時刻)。しかし Cloud Logging には以下の仕様があるので開発者が独自にアクセスログを出力する場合、アクセスログの時刻にはレスポンスを返す直前の時刻をセットする必要があります(ログの最終時刻)。

5.child のログの時刻が、parent のリクエスト処理内の時刻であること (つまり >child.timestamp >= parent.timestamp — parent.httpRequest.latency && >child.timestamp <= parent.timestamp)

ちなみに Cloud Run のアクセスログの時刻は GAE とは違いレスポンス時刻がセットされています。GAE のアクセスログの時刻仕様が特殊ということです。^[4]

アクセスログのSeverityには何を設定すべきか

アクセスログの Severity にはアプリケーションログにセットされた Severity の最大値をセットします。またログが一つも出力されなかった場合は、HTTP ステータス200(正常)のときは INFO に、HTTP ステータス400(クライアントエラー)または500(サーバエラー)の場合は ERROR にセットするのが良いと思います。
アプリケーションログの最大値を管理するのは context.Context を使って管理するのがおすすめです。

アクセスログとアプリケーションログのlogNameに別の名前をセットするためのハック

ログのグルーピングには以下の仕様があります。

2.parent, child で log ID (logName) が別々であること

アクセスログとアプリケーションログの logName に別の名前をセットしないといけないということです。ただ logName は開発者側が自由にセットできるフィールドではないためアクセスログを Stderr に、アプリケーションログを Stdout に出力するなどして無理やり logName を変えてやる必要があります。

標準出力のlogName

• projects/[PROJECT_ID]/logs/stdout

標準エラー出力のlogName

• projects/[PROJECT_ID]/logs/stderr

アクセスログを出力する

ここまで内容をふまえ実装すると以下のようになります。

req := HTTPRequest{
    RequestMethod: "GET",
    RequestURL:    "/hello_world",
    RequestSize:   1024,
    Status:        200,
    ResponseSize:  1024,
    UserAgent:     "PostmanXXXX",
    RemoteIP:      "127.0.0.1",
    ServerIP:      "127.0.0.2",
    Referer:       "referer",
    Latency:       MakeDuration(3*time.Second),
    Protocol:      "HTTP/1.1",
}
ety := &AccessLog{
    Severity:    "INFO",
    Time:        time.Now(), // レスポンスを返す直前の時刻をセットすること
    Trace:       "projects/[PROJECT-ID]/traces/[TRACE-ID]",
    HTTPRequest: req,
}
// Stderrに出力する. アプリケーションログはStdoutに出力する想定
if err := json.NewEncoder(os.Stderr).Encode(ety); err != nil {
    fmt.Printf("failed to write log: %v", err)
}

Latency は Middleware を使って開始時間と終了時間を計測してセットするのが良いと思います。
また RequestSize と Status は標準の http.ResponseWriter では取得できないのでこんな感じの実装が必要です。

gRPCのアクセスログはどうするのが良いか

Cloud Logging のログのグループ化は現状 HTTP にしか対応していません。gRPC の場合は gRPC リクエストのメタ情報から HTTP リクエストを疑似的に生成する必要があります。コードをここで紹介すると長くなるので割愛しますが、もし興味があれば以下の実装例を見てみてください。

• UnaryServerInterceptor

アクセスログとアプリケーションログの関係

ここまでアクセスログとアプリケーションログの実装をみてきましたが、情報整理するためにアクセスログの構造体とアプリケーションログの構造体の関係を図にしました。

図にしてみるとわかりますが、両者の基本構成の違いはアクセスログの httpRequest と アプリケーションログの message だけです。意外とシンプルです。

まとめ

ログの種類は2種類

• アクセスログ
• アプリケーションログ

理想のログ出力は以下が満たされていること

1. 障害検知に優れている
2. お問い合わせやバグの調査がしやすい
3. メトリクスが簡単に作成でき監視に活用できる
4. うっかり個人情報が流れてこない(今回は除外)

これをログ出力で実現するには以下が実装できれば良い

• アプリケーションログを一つのログとして独立させる
• アプリケーションログを構造化して出力し、横串での検索やメトリクス作成ができるようにする
• アクセスログにアプリケーションログが関連づけられている

GAEとCloud Runはアクセスログが自動で出力されるので自動出力されたアクセスログのtraceと文字列をアプリケーションログのtraceにセットすればログがグルーピングされる
GKE はアクセスログが自動で出力されないのでアクセスログを開発者が自前で出力する必要がある

その辺うまいことやってくれるライブラリを開発しました

そのあたりうまいことやってくれるロギングライブラリを開発したので是非使ってみてください。
https://github.com/glassonion1/logz

使い方はこんな感じです。別パッケージにて Gin や Echo のミドルウェアと gRPC のインタセプターも提供してます。

package main

import (
    "log"
    "net/http"

    "github.com/glassonion1/logz"
    "github.com/glassonion1/logz/middleware"
)

func main() {
    mux := http.NewServeMux()
    mux.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
        ctx := r.Context()

        // Writes info log
        logz.Infof(ctx, "writes %s log", "info")
    })

    logz.SetProjectID("your gcp project id")
    logz.InitTracer()
    // Sets the middleware
    h := middleware.NetHTTP("tracer name")(mux)

    log.Fatal(http.ListenAndServe(":8080", h))
}

ログはこんな感じに出力されます。

参考:ログのグループ化に対応したライブラリ

ログのグループ化に対応したライブラリはいくつかあります。これらライブラリの機能を比較したいと思います。

• aelog
• sdlog
• stackdriver-request-context-log
• logz

	アプリケーション ログ	アクセスログ	Middleware 提供	GAE/CloudRun	GKE	appengine/log 互換	連携トレーサー ライブラリ
aelog	○	×	○	○	×	○	OpenCensus
sdlog	○	△※1	×	○	×	○	OpenCensus
context-log	○	○	○	△※2	○	×	OpenCensus
logz	○	○	○	○	○	○	OpenTelemetry

△※1...定義のみ
△※2...ライブラリが出力するアクセスログが正しく出力されない

参考記事

• GAE のログに憧れて
• AppEngineの旧Log APIを脱却したい話
• GAE/Go1.12 において構造化ログを出力する
• CloudRun で GAE のログを再現する
• Stackdriver Logging(Log Viewer)で見た目の良いログを出力するためのあれこれ
• ログの書き込みと表示
• 構造化ペイロードの特殊フィールド
• LogSeverity

脚注

1. この記事で Google App Engine(GAE)と表記する場合は Google App Engine standard edition のことを指します。

2. 時々、構造化ログ=ログのグループ化という文脈で書かれた記事を見かけますが、構造化ログとログのグループ化は直接関係がありません。構造化ログのデータを良い感じセットするとログのグループ化ができるというだけです。

3. プロキシとしてESPv2を使うとGKEでもX-Cloud-Trace-Contextヘッダがセットされます。

4. GAEのアクセスログにはoperationがセットされているがCloud Runのアクセスログにはセットされてないなど他にも違いがあります。