Zenn
🧱

【Go】 Cloud Logging with log/slog package

2023/09/24に公開
Go
Google Cloud
Cloud Logging
slog
tech

はじめに

皆さんはGo1.21から導入されたlog/slogパッケージは使っていますでしょうか？
この記事では、slogを利用してCloud Loggingのログエクスプローラをより活用するための方法をまとめてみました。

この記事に絡んだ実装はこちらのリポジトリにあります。

対象読者

  • Google Cloudをお使いの方
  • Google CloudにデプロイしたGoアプリケーションのログが見づらくて困っている方
  • slogの使い方を知りたい方

log/slogについて

log/slogは、日本時間の2023年8月9日にリリースされたGo1.21の標準パッケージとして導入されたロギングのためのパッケージです。
構造化したログを出力するのに便利な仕組みが用意されています。
🪵 Go1.21 log/slogパッケージ超入門という記事に情報がよくまっていますので、詳しく知りたい方はそちらの記事や https://pkg.go.dev/log/slog をご覧ください。
(上記記事には大変お世話になりました)

Cloud Loggingの構造化ロギングについて

Cloud Runなどにデプロイしたアプリケーションが標準出力や標準エラーなどにログを書き込むと、Cloud Loggingにログが収集されます。
このとき、決められたフォーマットでログを出力することで、ログエクスプローラ上での検索効率を向上させ、障害発生時や開発時などの調査が格段にやりやすくなります。
詳しくは構造化ロギング  |  Cloud Logging  |  Google Cloud とLogEntry  |  Cloud Logging  |  Google Cloudのドキュメントに記載されています。

準備

ここからは、サンプルコードとログエクスプローラのキャプチャを使ってslogを使った構造化ロギングの例を紹介します。
WebアプリケーションをCloud Runにデプロイする想定で進めていきます。

HTTPサーバを構築する

/pingというエンドポイントを持つアプリケーションを作ります。
このエンドポイントにリクエストが来ると、pongという文字列を返すようにします。

http.Handle("/ping", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
  w.Write([]byte("pong"))
}))
s := &http.Server{
  Addr:    ":" + port,
  Handler: handler,
}
if err := s.ListenAndServe(); err != nil && err != http.ErrServerClosed {
  panic("failed to close: %v", err)
}

slogを使ってリクエストの情報を出力するミドルウェアを作る

package middlewares

func LoggerMiddleware(next http.Handler) http.Handler {
  return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
    next.ServeHTTP(w, r)
    go func() {
      l := slog.New(slog.slog.NewJSONHandler(o.Writer, &slog.HandlerOptions{
        AddSource:   true,
        Level:       slog.LevelInfo,
      }))
      l.InfoContext(r.Context(), "request", "method", r.Method, "path", r.URL.Path)
    }()
  })
}

上記のミドルウェアをHTTPサーバに登録します。

s := &http.Server{
  Addr:    ":" + port,
  Handler: middlewares.LoggerMiddleware(handler),
}

デプロイ後のログエクスプローラのキャプチャはこちらです。

JSON形式のログが表示されていることが分かります。

{"level":"INFO", "method":"GET", "msg":"request", "path":"/ping", "source":{…}}

ただし、ログとしてはlevel: INFOを指定したのにも関わらず、エクスプローラ上はデフォルトとなっています。(キャプチャ左上)

実践

ここからはLogEntryの仕様に則ってログを出力していきます。

slogのキーを置き換えてログエクスプローラの表示を変更する

先程のサンプルコードのようにslogのハンドラにAddSource: trueとしてオプションを渡すとlevel、msg、sourceというキーを持ったログを出力します。これらはslog.Attrとして定義されています。

LogEntryの仕様を見ると、levelはseverity、sourceはlogging.googleapis.com/sourceLocationに置き換えることができます。

slogのハンドラのオプションにはReplaceAttrを渡すことができるため、そちらを利用してJSONのフィールドを置き換えていきます。

func LoggerMiddleware(next http.Handler) http.Handler {
  return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
    next.ServeHTTP(w, r)
    go func() {
      l := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
        AddSource:   true,
        Level:       slog.LevelInfo,
        ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
          switch a.Key {
          case slog.LevelKey:
            a = slog.Attr{
              Key:   "severity",
              Value: a.Value,
            }
          case slog.SourceKey:
            a = slog.Attr{
              Key:   "logging.googleapis.com/sourceLocation",
              Value: a.Value,
            }
          }
          return a
        },
      }))
      l.InfoContext(r.Context(), "request", "method", r.Method, "path", r.URL.Path)
    }()
  })
}

デプロイ後のログエクスプローラのキャプチャはこちらです。

INFOレベルのログとして認識され、sourceLocationが適切なフィールドに置き換えられていることが分かります。
それにより、先程は{"level":"INFO", "method":"GET", "msg":"request", "path":"/ping", "source":{…}}として表示されていた部分が{"method":"GET", "msg":"request", "path":"/ping"}と読みやすくなりました。

カスタムラベルを付与する

LogEntryにはユーザー定義のラベルを付与することができます。
logging.googleapis.com/labelsというキーに対して、mapを値として渡すことで機能します。
slog.AttrにはネストしたAttrを表現するためのslog.Groupという関数があるため、そちらを利用します。

ユーザを特定するためのUIDをログに含めることを考えてみます。
(※実際には、コンテキスト経由でUIDを取得してログに含めることになると思います。)

l := slog.New(slog.slog.NewJSONHandler(os.Stdout, ...)).With(
  slog.Group("logging.googleapis.com/labels",
    slog.String("uid", "1234567890"),
  ),
)

デプロイ後のログエクスプローラのキャプチャはこちらです。

labels.uidとして値が表示されていることが分かります。
なお、ログエクスプローラではJSONフィールドの値を分かりやすく可視化してくれる機能があります。
labels.uidの値をクリックし、オプションを選択すると、以下のように表示されます。


ログの行にChip UIとしてUIDを表示することができ、どのユーザからのリクエストなのかが一目で分かるようになりました。

ログをグルーピングする

ここまでで、ログを構造化していくことができました。
しかし、そのログは一体どのリクエストに紐づくログなのかが分かりにくいと思います。
秒間リクエスト数の多いアプリケーションはなおさらです。
そこで、トレースという仕組みを使ってログをグルーピングしていきます。

トレースは、logging.googleapis.com/traceというキーに対して、projects/{project_id}/traces/{trace_id}という形式の値を渡すことで機能します。[1]

Cloud Runではデフォルトでtraceparentヘッダが入力されるため、これを利用します。[2]
このtraceparentに含まれるトレースの伝播を簡単にするため、otelhttpパッケージを利用します。
こちらの記事が参考になります。分散トレースをデプロイしてマイクロサービスのレイテンシを監視する  |  Cloud アーキテクチャ センター  |  Google Cloud
(※OpenTelemetryに関しての説明を書くと長くなってしまうため、ここでは割愛します。)

HTTPハンドラの変更

traceparentヘッダをGoコンテキストに展開するため、otelhttp.NewHandlerによってミドルウェアを作成します。

tp := trace.NewTracerProvider()
defer tp.Shutdown(ctx)
otel.SetTracerProvider(tp)
otel.SetTextMapPropagator(autoprop.NewTextMapPropagator())

mux := http.NewServeMux()
mux.Handle("/ping", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
  w.Write([]byte("pong"))
}))

handler := otelhttp.NewHandler(middlewares.LoggerMiddleware(mux), "server")
s := &http.Server{
  Addr:    ":" + port,
  Handler: handler,
}

このようにすると、当該ミドルウェアのGoコンテキストから、トレースコンテキストを取得することができます。

sc := trace.SpanContextFromContext(ctx)

ログにトレースを付与する

トレースが取得できたらログに埋め込むようにします。

l := slog.New(slog.NewJSONHandler(os.Stdout, ...)).With(
  slog.Group("logging.googleapis.com/labels",
    slog.String("uid", "1234567890"),
  ),
)
sc := trace.SpanContextFromContext(ctx)
if sc.IsValid() {
  trace := fmt.Sprintf("projects/%s/traces/%s", os.Getenv("GOOGLE_CLOUD_PROJECT"), sc.TraceID().String())
  l = l.With(
    slog.String("logging.googleapis.com/trace", trace),
    slog.String("logging.googleapis.com/spanId", sc.SpanID().String()),
    slog.Bool("logging.googleapis.com/trace_sampled", sc.TraceFlags().IsSampled()),
  )
}

デプロイ後のログエクスプローラのキャプチャはこちらです。

UIDのChipの横に、マークがついているのが分かるでしょうか？
これは、ログがトレースに紐づいていることを示しています。
クリックすると、オプションが標示されます。

このトレースのエントリを表示をクリックすると、紐づくトレースを一覧することができます。
どのリクエストに紐づくログなのかが分かるようになりました。
エラーログなどを調査する際に、特定のリクエストに紐づくログを一覧することができるので、非常に便利です。

トレースの詳細表示をクリックすると、トレースの情報を確認することができます。

Tips

slogのカスタムハンドラの作成

slog.Handlerはインタフェースとなっているため、それを満たす構造体を作成することでカスタムハンドラを作成することができます。
上記のトレースの処理や、カスタムラベルの埋め込み処理などをハンドラに移譲することで、ミドルウェアの処理をシンプルにすることができます。

https://github.com/hytkgami/slog-tracer/blob/main/internal/logger/logger.go

ログエクスプローラでの検索

上記の例で出力したログをJSONで表すとこのようになっています。

{
  "insertId": "6510082c000cdfe818932bc4",
  "jsonPayload": {
    "method": "POST",
    "path": "/ping",
    "message": "{\"title\":\"hello\"}"
  },
  "resource": {
    "type": "cloud_run_revision",
    "labels": {
      "service_name": "slog-tracer",
      "revision_name": "slog-tracer-00014-6kc",
      "project_id": "hytkgami-develop",
      "configuration_name": "slog-tracer",
      "location": "asia-northeast1"
    }
  },
  "timestamp": "2023-09-24T09:58:04.843151916Z",
  "severity": "INFO",
  "labels": {
    "uid": "1234567890",
    "instanceId": "00fd0ee57bef17aaa8539121dfcc6865a4d5efdcf440a2ba695a37fadfdc9cbe66d6f54cde0306f031b18b8ac0ca6e8453658b7903b641875daab3c86bde699b598f5c"
  },
  "logName": "projects/hytkgami-develop/logs/run.googleapis.com%2Fstdout",
  "trace": "projects/hytkgami-develop/traces/6948f946260c039a1729dce392a6e0e2",
  "sourceLocation": {
    "file": "github.com/hytkgami/slog-tracer/internal/middlewares/logger_middleware.go",
    "line": "90",
    "function": "github.com/hytkgami/slog-tracer/cmd/server.Run.LoggerMiddleware.func3.2"
  },
  "receiveTimestamp": "2023-09-24T09:58:04.848918157Z",
  "spanId": "9e3f26a0432becef",
  "traceSampled": true
}

このとき、ログエクスプローラ上では以下のようなクエリを使うことができます。

  • jsonPayload.path="/ping"
  • trace="projects/hytkgami-develop/traces/6948f946260c039a1729dce392a6e0e2"
  • labels.uid="1234567890"

また、アクセスログのようにhttpRequestがログに含まれている場合、レイテンシの検索も可能です。

{
  "insertId": "650ee9db000025782a37e568",
  "httpRequest": {
    "requestMethod": "GET",
    "requestUrl": "https://xxxx.a.run.app/ping",
    "requestSize": "369",
    "status": 200,
    "responseSize": "710",
    "userAgent": "RapidAPI/4.0.0 (Macintosh; OS X/13.5.2) GCDHTTPRequest",
    "remoteIp": "xxxx",
    "serverIp": "xxxx",
    "latency": "0.112373540s",
    "protocol": "HTTP/1.1"
  },
  "resource": {
    "type": "cloud_run_revision",
    "labels": {
      "project_id": "hytkgami-develop",
      "service_name": "slog-tracer",
      "location": "asia-northeast1",
      "configuration_name": "slog-tracer",
      "revision_name": "slog-tracer-00003-p4m"
    }
  },
  "timestamp": "2023-09-23T13:36:26.792725Z",
  "severity": "INFO",
  "labels": {
    "instanceId": "00fd0ee57ba46a6c180245806b36c36c782cc02c5675397a622e693b19528acdd45b4d5092dca4216ee5c557e345c037d524cf824087878dd09107d4e24f12bf35"
  },
  "logName": "projects/hytkgami-develop/logs/run.googleapis.com%2Frequests",
  "trace": "projects/hytkgami-develop/traces/92869b3630e29527b93c350b9c47165c",
  "receiveTimestamp": "2023-09-23T13:36:27.015623151Z",
  "spanId": "17818140024819766940",
  "traceSampled": true
}
  • httpRequest.latency>"1s"

処理の遅い箇所を特定するのに役立つかも知れません。
(実際にはCloud Traceなどを利用してボトルネックを特定していくことになると思います。)

まとめ

slogを使ったCloud Loggingでの構造化ロギングについてご紹介しました。
調査に必要なデータをログに含めておくことで、ログエクスプローラ上での検索効率を向上させることができます。

脚注

  1. https://cloud.google.com/logging/docs/structured-logging?hl=ja#special-payload-fields ↩︎

  2. https://cloud.google.com/run/docs/trace?hl=ja ↩︎

Discussion