Go logLevel設計 logrus echo

今回はGo言語でログ出力を実装します。 Go言語には標準でlog パッケージがありますが、今回はよりリッチな logrus を使ったログ設計を行なっていきます。

レベル設計

ログをレベル単位で分けることでバグの検出を容易にするだけでなく、特定のレベルが出力されたらslackに通知するといった事もできるようになります。

今回は以下のように設計しました。

レベル	説明	slack通知
debug	開発時に使う出力	なし
info	障害があったときに参考になる情報	なし
warn	警告 緊急性の低いエラー	出力する
error	対処が必要なエラー	@here 付きで出力
fatal	システムが継続不能なエラー	@here 付きで出力

エラーコードのマッピング

上記で設計したログレベルに対して独自に定義した以下のエラーをマッピングします。

今回はデモなので DB系のエラーを２種類のみ用意しました。

• NotFound: dbからデータが見つからない
• Database: 接続エラーなど

package errorcode

type ErrorCode string

const (
    NotFound         ErrorCode = "notfound_error"
    Database         ErrorCode = "database_error"
)

マッピングは以下とします。

errorcode	logLevel
NotFound	info
Database	warn

以上までが設計となります。 次から実装を行なっていきます。

実装

今回はechoでサーバーを構築しています。 main関数で必要なmiddlewareを注入します。

   middlewares := []echo.MiddlewareFunc{
                 // 省略
        middleware.NewInjectRequestID(),
        middleware.NewInjectLogger(),
    }

log出力の為に requestIDの付与とLogger自体の生成を行うmiddlewareです。

middleware requestID

各リクエストに対してrequestIDを付与します。 requestIDはechoから提供されているパッケージもありましたが、今回は不要なので直接uuidを付与しています。

package middleware

import (
    "context"

    "github.com/repo/backend/src/infra/logger"
    "github.com/google/uuid"
    "github.com/labstack/echo"
)

type key string

const (
    REQUEST_ID_KEY key = "requestID"
)

func NewInjectRequestID() echo.MiddlewareFunc {
    return func(h echo.HandlerFunc) echo.HandlerFunc {
        return func(c echo.Context) error {
            requestID := c.Request().Header.Get("X-Request-ID")
            if requestID == "" {
                requestID = uuid.NewString()
            }

            newCtx := context.WithValue(c.Request().Context(), REQUEST_ID_KEY, requestID)
            c.SetRequest(c.Request().WithContext(newCtx))
            return h(c)
        }
    }
}

func GetRequestID(ctx context.Context) string {
    requestID := ctx.Value(REQUEST_ID_KEY)

    if target, ok := requestID.(string); ok {
        return target
    } else {
        logger.Fatal("cannot get requestID from Context")
        panic("")
    }
}

middleware logger

上記で生成したrequestIDを取得し、loggerを生成しcontextにセットしています。 *loggerの実装は後述します

package middleware

import (
    "github.com/repo/backend/src/infra/logger"
    "github.com/repo/backend/src/util/appcontext"
    "github.com/labstack/echo"
)

func NewInjectLogger() echo.MiddlewareFunc {
    return func(h echo.HandlerFunc) echo.HandlerFunc {
        return func(c echo.Context) error {
            requestID := GetRequestID(c.Request().Context())
            logger := logger.New(requestID)
            newCtx := appcontext.SetLogger(c.Request().Context(), logger)
            c.SetRequest(c.Request().WithContext(newCtx))
            return h(c)
        }
    }
}

middlewareの実装は以上です。

logger パッケージ

次にlogrusをラップする独自のloggerパッケージを実装します。 infra層に実装しておけばlogrusから変更する時も容易です。

package logger

import (
    "bytes"
    "fmt"
    "os"
    "time"

    "github.com/sirupsen/logrus"
)

func init() {
    logrus.SetFormatter(&logrus.TextFormatter{
        DisableTimestamp: true,
        ForceColors:      true,
        PadLevelText:     true,
    })
    logrus.SetLevel(logrus.DebugLevel)
    logrus.SetOutput(&MyOutput{})
    logrus.SetFormatter(&MyFormatter{})
}

func New(requestID string) *logrus.Entry {
    return logrus.StandardLogger().WithFields(logrus.Fields{"requestId": requestID})
}

func Info(v ...interface{}) {
    logrus.Info(v...)
}

func Infof(format string, v ...interface{}) {
    logrus.Infof(format, v...)
}

func Debug(v ...interface{}) {
    logrus.Debug(v...)
}

func Debugf(format string, v ...interface{}) {
    logrus.Debugf(format, v...)
}

func Warn(v ...interface{}) {
    logrus.Warn(v...)
}

func Warnf(format string, v ...interface{}) {
    logrus.Warnf(format, v...)
}

func Error(v ...interface{}) {
    logrus.Error(v...)
}

func Errorf(format string, v ...interface{}) {
    logrus.Errorf(format, v...)
}

func Fatal(v ...interface{}) {
    logrus.Fatal(v...)
}

func Fatalf(format string, v ...interface{}) {
    logrus.Fatalf(format, v...)
}

type MyFormatter struct{}

func (f *MyFormatter) Format(entry *logrus.Entry) ([]byte, error) {
    var b *bytes.Buffer

    if entry.Buffer != nil {
        b = entry.Buffer
    } else {
        b = &bytes.Buffer{}
    }

    b.WriteString(entry.Time.Format(time.RFC3339))
    b.WriteString(" ")
    b.WriteString(fmt.Sprintf("[%s]", entry.Level))
    b.WriteString(" ")
    if entry.Data["context"] != nil {
        b.WriteString(fmt.Sprintf("(%v)", entry.Data["context"]))
        b.WriteString(" ")
    }
    if entry.Data["requestId"] != nil {
        b.WriteString(fmt.Sprintf("(%v)", entry.Data["requestId"]))
        b.WriteString(" ")
    }
    b.WriteString(fmt.Sprintf("%v", entry.Message))

    b.WriteByte('\n')
    return b.Bytes(), nil
}

type MyOutput struct{}

func (splitter *MyOutput) Write(p []byte) (n int, err error) {
    if bytes.Contains(p, []byte("[debug]")) || bytes.Contains(p, []byte("[info]")) {
        return os.Stdout.Write(p)
    }
    return os.Stderr.Write(p)
}

init()関数でlogrusの設定を行います。 SetOutput SetFormatter ではlogrusが提供しているinterfaceを満たす事でカスタマイズしています。

ログ出力の関数 Info()やWarn()はlogrusのメソッドをそのままラッピングしているだけです。

logを出力したい箇所でこれらの関数を呼び出します。

HandleError

loggerパッケージを実装できたのでエラーハンドリングを行なっている関数で呼び出しを行なっていきます。

func HandleError(ctx context.Context, err apperror.AppError) {
    logger := appcontext.GetLogger(ctx)

    var msg string

    msg += fmt.Sprintf("%+v", err)

    switch err.Code() {
    case errorcode.NotFound:
        graphqlerr.AddErr(ctx, getInfoMessage(err), graphqlerr.NOT_FOUND_ERR)
        logger.Info(msg)
    case errorcode.Database:
        graphqlerr.AddErr(ctx, getInfoMessage(err), graphqlerr.NOT_FOUND_ERR)
        logger.Warn(msg)
    }
}

contextからloggerを取り出し、各エラーコードに対してlogの呼び出しを行なっています。 ※GraphQLで実装しているのでそのエラーハンドリングもしています。

呼び出し元のResolver(コントローラー)は以下のように実装されています。

func (r *queryResolver) Task(ctx context.Context, id string) (*gmodel.Task, error) {
    var task gmodel.Task

    if err := r.db.First(&task, id).Error; err != nil {
        if errors.Is(err, gorm.ErrRecordNotFound) {
            gql.HandleError(
                ctx,
                apperror.New("new error").Info("this is Info1").SetCode(errorcode.NotFound),
            )
        } else {

            gql.HandleError(
                ctx,
                apperror.Wrap(err, fmt.Sprintf("failed to get task id = %s", id)).SetCode(errorcode.Database),
            )
        }
        return nil, nil
    }

    return &task, nil
}

Taskを検索する単純なAPIです。DBに存在しない場合は NotFound それ以外のエラーは Databaseエラーを返しています。

それでは試しにAPIを叩いて出力してみます。

[10:21:32][APP] :    ____    __
[10:21:32][APP] :   / __/___/ /  ___
[10:21:32][APP] :  / _// __/ _ \/ _ \
[10:21:32][APP] : /___/\__/_//_/\___/ v3.3.10-dev
[10:21:32][APP] : High performance, minimalist Go web framework
[10:21:32][APP] : https://echo.labstack.com
[10:21:32][APP] : ____________________________________O/_______
[10:21:32][APP] :                                     O\
[10:21:32][APP] : ⇨ http server started on [::]:8080
[10:21:32][APP] : 
[10:21:32][APP] : 
[10:21:32][APP] :  // Databaseエラー
[10:21:37][APP] : 2022-01-03T10:21:37Z [warning] (a1d2b095-7a3e-434d-a593-d832020f006f) new error:
[10:21:37][APP] :     github.com/DaisukeMatsumoto0925/backend/src/graphql/resolver.(*queryResolver).Task
[10:21:37][APP] :         /app/src/graphql/resolver/task.resolver.go:251
[10:21:32][APP] : 
[10:21:32][APP] : 
[10:21:32][APP] :   // NotFoundエラー
[10:21:37][APP] : 2022-01-03T10:21:37Z [info] (a1d2b095-7a3e-434d-a593-d832020f006f) new error:
[10:21:37][APP] :     github.com/DaisukeMatsumoto0925/backend/src/graphql/resolver.(*queryResolver).Task
[10:21:37][APP] :         /app/src/graphql/resolver/task.resolver.go:256

無事に出力することができました。 今回は以上となります。

最後に、 このブログではweb開発について発信していくのでまたご覧頂けると嬉しいです。 最後までお読み頂きありがとうございました。