MORITOMOMENT

登山好きエンジニアのテックブログ

プログラミング・アウトドア関連を中心に発信

[Golang] Cloud Runでログレベルを管理できるように構造化ログを出力するように実装してみた

Golang API GCP プログラミング

f:id:moritomo7315:20220219103043j:plain

まえおき

最近、GCPのCloud Runにデプロイしてサービスを稼働させようしています。

実際にCloud RunでDEV環境を用意して動かしてみたりしてますが、エラーの場合のログでもそのまま出力するだけでは、GCP上でDefaultのログと判別されてしまいます。

ログを効果的に管理するためにはGCPのフォーマットに合わせた構造でログを出力する必要があるみたいです。

ユーザから何か問い合わせがあった場合などにはログレベルでフィルタできると調査が便利ですし、 監視においてもloglevelがERRORでならアラート通知を飛ばすなどの仕組みもつくることができます。

uber開発のzapなど、OSSのLoggingライブラリも豊富ですが 今回は標準logライブラリのみで対応してみたいと思います

今回のサンプルプログラム

github.com

GCPのログのフォーマット

GCPの構造化ログのフォーマットは下記の公式ドキュメントにまとまっています。

cloud.google.com

この中でも必須だろうなというものが

実装してみる

構造化ログ用の構造体を作成

severityとmessageを持つ構造体を定義します。 GCPの公式ドキュメントのままですがencoding/jsonでjson形式の文字列に変換できるようにメソッドも用意しました。

cloud.google.com

package model

import (
    "encoding/json"
    "log"
)

// ログレベルの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"`
}

// 構造体を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)
}

ログレベルごとにlog出力するメソッドを定義

もっと綺麗で無駄のない書き方があると思うが現時点では一旦このままにしておきます。のちにリファクタリングします。

// go-user-rest-api/infrastructure/gcplogger/log_entry.go
package gcplogger

import (
    "github.com/MoriTomo7315/go-user-rest-api/domain/model"
)

// INFOレベルのログ出力
func InfoLogEntry(message string) string {
    entry := &model.LogEntry{
        Severity: model.INFO,
        Message:  message,
    }

    return entry.String()
}

// WARNレベルのログ出力
func WarnLogEntry(message string) string {
    entry := &model.LogEntry{
        Severity: model.WARN,
        Message:  message,
    }

    return entry.String()
}

// ERRORレベルのログ出力
func ErrorLogEntry(message string) string {
    entry := &model.LogEntry{
        Severity: model.ERROR,
        Message:  message,
    }

    return entry.String()
}

ログを出力する箇所を修正

標準logライブラリのフラグ設定

現在標準logライブラリでログ出力する時に、ファイル名や行数も一緒に出力するようにしている場合は下記のような修正をおこないます。

// log.SetFlags(log.LstdFlags | log.Lmicroseconds | log.Llongfile)
// ↓
log.SetFlags(0)

SetFlagsでファイル名などを表示するよう設定している場合、

2022/02/18 19:11:30.703533 /Users/hogehoge/go-user-rest-api/main.go:39: {"severity":"INFO","message":"/api/users   start"}

のように表示されてしまいGCP側が構造化ログと判断できない問題があります。

そのためこの2022/02/18 19:11:30.703533 /Users/hogehoge/go-user-rest-api/main.go:39:の接頭辞は出力しないように設定します。

log.Printf部分の修正

元々のログ出力の実装

import "log"

log.Printf("INFO [CreateUser] Application logic start")
log.Printf("ERROR firestoreからusersコレクションの検索に失敗 err=%v", err)

構造化ログを出力するように修正

import (
    "log"
    logger "github.com/MoriTomo7315/go-user-rest-api/infrastructure/gcplogger"
)

// INFO
log.Printf(logger.InfoLogEntry("[CreateUser] Application logic start"))

// ERROR
log.Printf(logger.ErrorLogEntry(fmt.Sprintf("firestoreからusersコレクションの検索に失敗 err=%v", err)))

ローカルで動作確認

curl localhost:50001/api/users/a でリクエストしてわざとエラー起こしてみると、INFOとERRORがちゃんとseverityにセットされており期待通り出力されています。

$ GO_ENV=local go run main.go
{"severity":"INFO","message":"/api/users   start"}
{"severity":"INFO","message":"[/api/users/] START ==========="}
{"severity":"INFO","message":"[GetUserById] Application logic start"}
{"severity":"INFO","message":"[GetUserById] connecting firestore start. id=a"}
{"severity":"ERROR","message":"firestoreからusersコレクションの検索に失敗 id=a, err=rpc error: code = NotFound desc = \"*****/documents/users/a\" not found"}
{"severity":"INFO","message":"start check and return error response"}
{"severity":"ERROR","message":"userが見つかりませんでした。 userId=a"}
{"severity":"INFO","message":"start creating response"}
{"severity":"INFO","message":"end creating response"}
{"severity":"INFO","message":"[/api/users/] END ==========="}

Cloud Runでも確認

これまでのログは下記のようにすべてDEFAULTレベルで認識されていたのでログレベルでフィルタリングができない状況でした。 f:id:moritomo7315:20220218193023p:plain

実際にCloud Runにデプロイして存在しないユーザをGETするリクエストをしてわざとINFOとERRORを確認してみます。

f:id:moritomo7315:20220219101301p:plain

ERRORレベルでのログの絞り込みもできるようになりました。

f:id:moritomo7315:20220219101436p:plain

まとめ

やったこと

  • goの標準log出力をGCPの構造化ログのフォーマットで出力するようにしてみた。
  • Cloud Runにデプロイして確認してみたところ無事ログが各ログレベルで出力されるようになった。
  • 標準logライブラリのファイル名表示などされなくなったが、ログの出力をgrepすれば調査はできるので一旦よしとします。

課題

  • サービス運用では同時に複数のアクセスが考えられるため、traceId等でログを追跡できるようにする必要があります。X-Cloud-Trace-Contextを使用してリクエストとログを一意にできるようにしたいです。
  • またCloud loggingなどの仕組みをつかってERRORのログをSlackに通知する仕組みとか作ってみようと思います。