マイクロサービスのロギングベストプラクティスとGoの実装の場合

こんにちは、プラットフォームチームの池田と申します。初投稿です。

プラットフォームチームではマイクロサービスアーキテクチャの構成を採用し開発を進めています。
どんな構成でも忘れてはいけないのがロギング。いわゆる非機能要件の1つで地味な存在ですが、サービス運用を支える上で非常に重要です。

直近でマイクロサービスにおけるロギングの構成を調査し、プラットフォームチームでメインで採用しているGo言語での実装を検証しました。
今回の記事ではそのまとめを紹介します。

目次

ロギングベストプラクティス for マイクロサービス

マイクロサービスにおけるロギングの方針に関して記載している日本語の記事が少なく感じたので、はじめに調べた結果のまとめを記載します。

リクエストにユニークなIDを付与し紐付けができるようにする

マイクロサービスでは、あるサービスAがサービスBを呼びさらにサービスCを呼ぶといった形になるので、呼び出しチェーンにユニークなIDを与えることで調査の見通しが良くなります。

このとき、アプリケーションがHTTPレスポンスなどでエラーを返す場合にもリクエストのユニークIDを入れると良いようです。そうすることで、問題が発生し際ユーザが受け取ったエラーとユニークIDを素早く紐付けて調査を開始することができます。

ユニークなIDをどこでどのように生成かということも重要なポイントでしょう。原則としてはユニークIDでの追跡範囲のエントリーポイントとなる箇所で生成します。そしてそういった箇所で利用されるロードバランサのサービス(AWSではELB)やKongなどのAPI Gatewayミドルウェアがプラグイン的にCorrelation ID(ユニークID)生成の機能を提供しているので、それを利用するのが一般的なようです。そういった機能では、生成したユニークIDをオリジナルのHTTPヘッダーへ挿入します。

ログは一箇所に集める

上述での各サービスが出力するユニークID付きのログを横断的に調査するために、各サービスのログを一箇所に集中させることが次に重要になります。

このとき、アプリケーションがPush型として能動的にHTTPリクエストなどを使って集約場所へ登録するのではなく、ローカルストレージのファイルやAmazon Elastic File Systemといったクラウドのストレージに一旦預けた後に、LogstashやFluentdといったツールで集約場所へ連携することが望ましいとのことです。そうすることで、アプリケーションからログ集約という役割を切り離すことができます。

以下の図はここまでの2つのポイントを踏まえた構成の一例です。Amazon ELBがCorrelation ID(ユニークID)を生成しマイクロサービスサービス間で伝搬され、出力されたログはCloudWatch Logs Subscriptionの機能でElasticsearch Serviceへと集約させています。

ログデータを構造化する

マイクロサービスではログに持たせるフィールドは柔軟にしておきたい一方で、サービス共通でロギングデータのパースができるようにもしておきたいです。

そこでサービス共通でログデータのフォーマットを合わせましょう。JSONやLTSVといった構造化の形式を統一させることで持たせるフィールドも柔軟になり、共通で必須なフィールドを容易にパースすることができます。

ログに有益な情報を持たせる

マイクロサービスアーキテクチャにおいてログ情報として持つことが望ましいフィールドが以下になります。

どのサービスでも共通で持つのが望ましいフィールド

• 日時(タイムスタンプ)
• 対象のサービス名
• スタックトレース
• エラー発生源である外部サービス名やミドルウェア名

リクエストのエントリーポイントとなるサービスで持つのが望ましいフィールド

• リクエスト元のIPアドレス
• ユーザが利用したブラウザ名またはモバイルのOS名
• HTTPレスポンスコード

Go言語での実装例

上述のベストプラクティスの内容を踏まえて、Go言語の場合の共通ロギングライブラリとアプリケーションのサンプルを作っていきます。

はじめに、重要なのは具体的にどういったフィールドやフォーマット、出力先にするかをチーム間で議論し合意した上でそのルールを決めることでしょう。

ここでは、ロギングルールを決定できているという前提で進めていきます。

今回の記事ではソースコードすべて載せられていませんが、後述のサンプルAPIサーバを実行し、下記のようにユニークIDを想定したHTTPヘッダー付きでリクエストすると、

curl -H 'X-Transaction-ID:00A-abcdef-99B' http://service-hostname/v2/sample

APIサーバから以下のようなJSON形式のログが標準出力へ出力されます。(フォーマッティングは後付しました。)

{
   "level":"error",
   "msg":"SearchSample panic!",
   "request-id":"00A-abcdef-99B",
   "service-name":"MicroService01",
   "stack":"goroutine 6 [running]...スタックトレースが続く...",
   "time":"2020-03-15T23:39:58+09:00"
}

マイクロサービス共通で利用するロギングライブラリ

上述したマイクロサービスのロギングの共通ルールは共通ライブラリとしてサービス(チーム)間で共有されるべきです。

package logger

import (
    "github.com/sirupsen/logrus"
)

const (
    // XTransactionID はユニークIDのためのHTTPヘッダーのキー名です。
    XTransactionID = "X-Transaction-ID"
)

var (
    // Log は本パッケージのグローバルインスタンスです。
    Log = defaultLogger()

    // ServiceName は各アプリケーションのビルド時に ldflags を利用して埋め込まれます。
    // 下記はビルドの例です。
    // go build -ldflags "-X path/microservice-logging/logger.ServiceName=MicroService01"
    ServiceName = "not-set"
)

// Logger は公開インターフェースです。
type Logger interface {
    Debug(xTxID interface{}, msg string, fields ...Field)
    Info(xTxID interface{}, msg string, fields ...Field)
    Error(xTxID interface{}, msg string, fields ...Field)
}

// NewLogger は Logger インターフェースのコンストラクタです。
// 基本として、マイクロサービスのアプリケーションはこれを利用せずに Log インスタンスを利用することがルールです。
// 開発をする場合や調査をする場合などで Config を設定しこのメソッドを呼び出す。
func NewLogger(conf *Config) Logger {
    return newLogger(conf)
}

func defaultLogger() Logger {
    return newLogger(NewConfig()) //NewConfig() で共通ルールに基づくデフォルト設定がされる。
}

type logger struct {
    *logrus.Logger
    config *Config
}

func newLogger(config *Config) Logger {
    var l = logrus.New()
    {
        l.Level, _ = logrus.ParseLevel(config.minLevel.String())
        l.Formatter = config.formatter
        l.Out = config.out
    }
    return &logger{
        Logger: l,
        config: config,
    }
}

func (l *logger) Debug(xTxID interface{}, msg string, fields ...Field) {
    ...
}

func (l *logger) Info(xTxID interface{}, msg string, fields ...Field) {
    ...
}

func (l *logger) Error(xTxID interface{}, msg string, fields ...Field) {
    ...
}

上記の共通ロギングライブラリにおいて実装のポイントをピックアップすると以下になります。

• Goのロギングのライブラリには現時点(2020年3月時点)で、最も多くのGitHubスター数のあるlogrusを利用
• グローバル変数(Log)をエクスポートしそれだけを利用させるようにしている
• ログのフィールドに入れるサービス名(ServiceName)はアプリケーションのビルド時に組み込むようにしている
• インターフェースのメソッドの引数にユニークID(XTransactionID)を指定する

これらのポイントはあくまでも一例に過ぎません。どのように実装するかはチームでのコーディングポリシーなどに依存するでしょう。

続いて以下はロギング設定のコードです。デフォルト設定はマイクロサービスのルールとして決定した内容になります。

package logger

import (
    "io"
    "os"
)

// Config は Logger 設定の構造体です。
//
// formatter: Format type of logging, TEXT or JSON
// out:       io.Writer of the logger output
// minLevel:  Minimum level to out
type Config struct {
    formatter Formatter
    out       io.Writer
    minLevel  Level
}

// ConfigOption はFunctional Options Patternで
// Configのフィールドを設定するための関数型です。
type ConfigOption func(*Config)

// NewConfig は *Config のコンストラクタです。
//
// マイクロサービスのルールである各デフォルト設定
// Formatter: JSON
// Out:       STD OUT
// MinLevel:  Info
func NewConfig(options ...ConfigOption) *Config {
    config := &Config{
        formatter: Formatters.JSON,
        out:       os.Stdout,
        minLevel: Levels.Info,
    }
    for _, option := range options {
        option(config)
    }
    return config
}

func WithMinLevel(minLevel Level) ConfigOption {
    return func(c *Config) {
        c.minLevel = minLevel
    }
}

func WithFormatter(formatter Formatter) ConfigOption {
    return func(c *Config) {
        c.formatter = formatter
    }
}

func WithOut(out io.Writer) ConfigOption {
    return func(c *Config) {
        c.out = out
    }
}

上記の例では

• ログデータはJSON形式 (formatter: Formatters.JSON)
• ログの出力先は標準出力 (out: os.Stdout)

というルールをデフォルト設定としています。(脱線ですがGoのio.Writer, io.Readerはとても良いものです。)

これらの設定に関してもチームが持つインフラ構成や方針に影響されるものです。

共通ロギングライブラリを利用するアプリケーションコード

上記の共通ロギングライブラリを利用するアプリケーションの実装例は以下のようになります。

ここではGinフレームワークを利用したAPIサーバを想定しています。Ginのミドルウェア内でプログラムpanic時にスタックトレース付きでロギングします。

import (
    "fmt"
    "net/http"
    "runtime"

    "github.com/gin-gonic/gin"

    "path/microservice-logging/logger"
)

var (
    defaultStackSize = 4 << 10 // 4 kb
)

// Recovery はGinフレームワーク で利用するミドルウェアです。
// 下層からの panic をリカバリーしロギングとHTTPレスポンスセットを実施します。
func Recovery() gin.HandlerFunc {
    return func(c *gin.Context) {
        defer func() {
            if r := recover(); r != nil {
                err, ok := r.(error)
                if !ok {
                    err = fmt.Errorf("%v", r)
                }
                var (
                    stack  = make([]byte, defaultStackSize)
                    length = runtime.Stack(stack, true)
                )
                logger.Log.Error(
                    /* Request-ID */ c.Request.Header.Get(logger.XTransactionID),
                    /* msg */ err.Error(),
                    /* Additional fields */ logger.F("stack", fmt.Sprintf("%s ", stack[:length])),
                )
                c.AbortWithStatusJSON(http.StatusInternalServerError, &gin.H{
                    "errors": []string{"unexpected error"},
                })
            }
        }()
        c.Next()
    }
}

func main() {
    router := gin.New()
    {
        router.Use(
            Recovery(),
        )
    }
    ...
}

おわりに

ベストプラクティスな方針を知ることができましたが、どうやって実現するかはどうしても開発チームごとに工夫しながら作っていく必要があると思います。日々精進です💪

また、今回のロギング実装の例ではパフォーマンスに関する考慮が不足しています。

• メモリアロケーションがより効率的なzapというライブラリに切り替える
• リクエストをさばいた最後にまとめて出力するようバッファを利用する

といった改善案が考えられます。
今後こういった面でも検証する予定です。

それでは (^_^)/~

参考

• マイクロサービスアーキテクチャ オライリージャパン出版
• https://www.scalyr.com/blog/microservices-logging-best-practices
• https://docs.microsoft.com/ja-jp/azure/architecture/microservices/design/patterns
• https://hackernoon.com/capture-and-forward-correlation-ids-through-different-lambda-event-sources-220c227c65f5