はじめに

こんにちは！バイセルテクノロジーズテクノロジー戦略本部の藤澤です。私の所属しているプロジェクトでは Cloud Run 上に Go(echo) で書いた Web サーバーのコンテナを立て、それをバックエンドとして利用しています。ログの監視には GCP の Cloud Logging を利用しており、今回は Cloud Logging 上でログを見やすくする方法についていくつか紹介したいと思います。

はじめに
構造化ログを出力できるようにする
ログをグルーピングする
- リクエストの trace を取得する
- trace をログに出力する
ログレベルによって色分けする
エラーログにスタックトレースを表示する
- stack trace を取得する
- stack trace をログに出力する
まとめ

構造化ログを出力できるようにする

標準の log パッケージを利用しただけでは、以下のように簡素なログが出力されます。画像1つ目のログが標準パッケージから出力されたログ、2つ目のログはCloud Runがデフォルトで出力するアクセスログです。

log.Print("hogehoge")

今回ログまわりを改善するにあたって、まずはzapというライブラリを利用します。ライブラリの詳しい解説は割愛しますが、構造化ログを出力できるようになるなどログ出力周りを色々補助してくるライブラリです。

ドキュメントにある通り、ライブラリをインストールすれば簡単に利用できます。

go get -u go.uber.org/zap

以下のようにzapを利用してログを落とすと、json形式で構造化して出力することができるようになります。

import "go.uber.org/zap"

logger, _ := zap.NewProduction()
defer logger.Sync()
logger.Info("ほげほげ",
    zap.String("ふがふが", "fugafuga"),
    zap.String("ぴよぴよ", "piyopiyo"),
)

ログをグルーピングする

サーバーでは実際には同時にリクエストを処理するので、ログをただ落とすだけではどのリクエストに対して出力されたログかが分かりずらいという問題があります。

例えば、以下のように１つのリクエストで複数のログを落とすようにして、連続してアクセスしてみます。

time.Sleep(time.Second * 1)
logger.Info("hogehoge")
time.Sleep(time.Second * 1)
logger.Info("fugafuga")
time.Sleep(time.Second * 1)
logger.Info("piyopiyo")

Cloud Logging上ではログが出力された順番に並んで表示されるので、どのログがどのリクエストによるものかがわからなくなってしまいます。

ここでは、ログをリクエスト毎に一意に識別できる方法を紹介します。

リクエストの trace を取得する

Cloud Run で受けたリクエストにはX-Cloud-Trace-Contextというヘッダーがデフォルトでセットされています。構造は以下の通りです。

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

trace とは GCPのドキュメントにもあるとおり、リクエスト毎に一意の値となっており、前述したアクセスログにもtraceというフィールドにセットされて出力されています。

この trace を出力したいログに含めることで、アクセスログと同じ一意なリクエストのログとして識別できます。

以下のように、echo の middleware で trace を取得し、contextに保存しておきます。

type ctxKey struct{}

func traceMiddleware(next echo.HandlerFunc) echo.HandlerFunc {
    return func(c echo.Context) error {
        match := regexp.MustCompile(`([a-f\d]+)/([a-f\d]+)`).
            FindAllStringSubmatch(
                c.Request().Header.Get("X-Cloud-Trace-Context"),
                -1,
            )

        trace := match[0][1]

        ctx := context.WithValue(c.Request().Context(), ctxKey{}, trace)
        c.SetRequest(c.Request().WithContext(ctx))

        return next(c)
    }
}

e := echo.New()
e.Use(traceMiddleware)

trace をログに出力する

ログにこちらのドキュメントにある通りの形式で出力します。

{
  "logging.googleapis.com/trace": "projects/[PROJECT_ID]/traces/[TRACE_ID]"
}

contextからtraceを取得しzapの構造化ログの機能を利用してログにtraceの情報を付加して出力します。

trace := c.Request().Context().Value(ctxKey{}).(string)

traceField := zap.String(
    "logging.googleapis.com/trace",
    fmt.Sprintf("projects/%s/traces/%s", "*********", trace),
)
time.Sleep(time.Second * 1)
logger.Info("hogehoge", traceField)
time.Sleep(time.Second * 1)
logger.Info("fugafuga", traceField)
time.Sleep(time.Second * 1)
logger.Info("piyopiyo", traceField)

この状態でログを確認すると、以前とは違ってログの先頭にアイコンが表示されています。これはログがtraceされている場合に表示されます。

ログの詳細を開いてみると、traceキーに先ほど出力したtraceの値が入っていることが確認できます。

このtraceをCloud Loggingの検索条件位含めてみるとどうなるでしょうか。

以下のように、同じtraceが登録されているログのみに絞り込んで表示することができます。 traceはリクエスト毎に一意のものなので、表示されたログは同じリクエスト内で出力されたログであるということになります。

ログレベルによって色分けする

zap にはログレベルを指定してログを出力する機能がありますが、デフォルトの状態ではどのログレベルで出力しても、 Cloud Logging 上では全て Info レベルと同様の表示となってしまいます。

GCPのドキュメントによると以下のように、構造化ログのフィールドでログレベルを指定するフィールドを「severity」というキーで出力すれば Cloud Logging 上でもログレベルを認識することができるようです。

zapではデフォルトで既にlevelというキーでログレベルのフィールドが含まれているので、以下のようにして zap の初期化時にキーを「severity」とするように設定を追加します。

config := zap.NewProductionConfig()
config.EncoderConfig.LevelKey = "severity"

logger, _ := config.Build()
defer logger.Sync()

するとこのようにログレベルが認識されて、表示がわかりやすくなります。

エラーログにスタックトレースを表示する

例えば Go で error が発生し、error に関するログを出力したい場合、そのエラーに関するスタックトレースをログに含めて出力したいことがあると多います。 zapではログレベルError等で出力すればデフォルトでスタックトレースが含まれて出力されます。

しかし、スタックトレースの発生箇所はログを落とした場所からになるので、エラー処理の全ての場所にログを出力する処理を書かなければならず手間がかかります。

err := fmt.Errorf("error occured")
if err != nil {
  // ログを落とした場所がzapのスタックトレースの起点となるので
  // ここでログを落とさないといけない
  logger.Error(err.Error())
  return err
}

以下のように工夫することで、エラー処理時に毎回ログを出力することなくスタックトレース付きのエラーログを出力できます。

stack trace を取得する

ここではpkg/errorsというライブラリを利用して、エラー発生時の stack trace を取得します

go get github.com/pkg/errors

以下のようにエラー処理時に、pkg/errors でエラーをラップすると、 StackTrace()でerrors.Wrapを呼んだ場所のスタックトレースが取得できます。

import "github.com/pkg/errors"

err := fmt.Errorf("error occured")
if err != nil {
    // ここではログを出力する処理は要らない
    return errors.Wrap(err, err.Error())
}

stack trace をログに出力する

エラーログの出力については、echo のエラーハンドラを拡張します。以下のように HTTPErrorHandler を実装します。

func errorHandler(err error, c echo.Context) {
    logger, _ := zap.NewProduction()
    defer logger.Sync()

    if er, ok := err.(interface{ StackTrace() errors.StackTrace }); ok {
        logger.Error(
            err.Error(),
            zap.String(
                "stacktrace",
                // er.StackTrace()で得られるスタックトレースの起点は
                // errors.Wrapした場所
                fmt.Sprintf("%+v\n\n", er.StackTrace()),
            ),
        )
    }
}

エラーハンドラを echo に渡せば利用できます。

e := echo.New()
e.HTTPErrorHandler = errorHandler

以下のようにエラーログが出力でき、スタックトレースが内包されていることが確認できます。

まとめ

いかがでしたでしょうか。

標準の log パッケージのみ利用していた場合に比べて、かなりログが見やすくなったと思います。サービスの運用中は様々な障害やトラブルが起きますが、ログの解析はそれに対応する有効な手段となります。「備えあれば憂なし」、いざという時のための備えば怠らないようにしたいですね。

最後に、Buysell Technologiesではエンジニアを募集しています。少しでも興味がある方はぜひご応募ください！

herp.careers

バイセル Tech Blog

バイセル Tech Blogは株式会社BuySell Technologiesのエンジニア達が知見・発見を共有する技術ブログです。

Go(echo) + Cloud Run で Cloud Logging のログを見やすくする方法