はじめに

GoのフレームワークはEchoを使うことが最近は多いのですが、そのログ周りの機能を試してみようかと思います。

Echoのロガー

Echoにはロガーに関するサポートが以下の2つあります。

Logger Middleware : アクセスログを出力するミドルウェア
Logger : 通常のロガーデフォルトではJsonでログを出力してくれる

このブログでは2つ両方とも試してみたいと思います。
また、リクエストにIDを割与えるRequest ID Middlewareも存在しておりこちらもLoggerに少し関わる機能を持っているので試してみようと思います。

動かす

環境

今回の動作環境は以下のような感じです。

$ go version
go version go1.17.1 linux/amd64

$ uname -srvmpio
Linux 5.4.0-88-generic #99-Ubuntu SMP Thu Sep 23 17:29:00 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

$ lsb_release -a
LSB Version:    core-11.1.0ubuntu2-noarch:security-11.1.0ubuntu2-noarch
Distributor ID: Ubuntu
Description:    Ubuntu 20.04.3 LTS
Release:    20.04
Codename:   focal

このLogger MiddlewareはLoggerWithConfigでカスタマイズすることができます。
例えば以下のようにすると任意のフォーマットでよりシンプルなロガーを出力することができます。

server go

func main() {
    e := echo.New()

    // 削除
    //e.Use(middleware.Logger())

    // 追加
    e.Use(middleware.LoggerWithConfig(middleware.LoggerConfig{
        Format: "time=${time_rfc3339_nano}, method=${method}, uri=${uri}, status=${status}\n",
    }))

    e.GET("/", func(c echo.Context) error {
        return c.String(http.StatusOK, "Hello, World!")
    })
    e.Logger.Fatal(e.Start(":1323"))
}

出力されるログは次の通りになります。

time=2021-10-15T08:56:03.378067938+09:00, method=GET, uri=/, status=200

サンプルアプリの作成

ベースとなるプロジェクトとサンプルアプリを作成します。
公式にあるやり方をさっくりとなぞります。

$ mkdir echo-logger && cd echo-logger

$ go mod init echo-logger
go: creating new go.mod: module echo-logger

$ go get github.com/labstack/echo/v4
go get: added github.com/labstack/echo/v4 v4.6.1
go get: added github.com/labstack/gommon v0.3.0
go get: added github.com/mattn/go-colorable v0.1.8
go get: added github.com/mattn/go-isatty v0.0.14
go get: added github.com/valyala/bytebufferpool v1.0.0
go get: added github.com/valyala/fasttemplate v1.2.1
go get: added golang.org/x/crypto v0.0.0-20210817164053-32db794688a5
go get: added golang.org/x/net v0.0.0-20210913180222-943fd674d43e
go get: added golang.org/x/sys v0.0.0-20210910150752-751e447fb3d0
go get: added golang.org/x/text v0.3.7

次に以下のファイルを作成してEchoのインスタンスを作りハンドラーを登録します。

server.go

package main

import (
    "net/http"
 
    "github.com/labstack/echo/v4"
)

func main() {
    e := echo.New()
    e.GET("/", func(c echo.Context) error {
        return c.String(http.StatusOK, "Hello, World!")
    })
    e.Logger.Fatal(e.Start(":1323"))
}

アプリを起動します。

$ go run server.go 

   ____    __
  / __/___/ /  ___
 / _// __/ _ \/ _ \
/___/\__/_//_/\___/ v4.6.1
High performance, minimalist Go web framework
https://echo.labstack.com
____________________________________O/_______
                                    O\
⇨ http server started on [::]:1323


$ curl localhost:1323
Hello, World!

これで下準備は完了です。

Logger Middlewareを使う

前述の通り、Logger Middlewareはアクセスログを出力してくれます。
使い方は超簡単で、以下のように

server.go

package main

import (
    "github.com/labstack/echo/v4"
    "github.com/labstack/echo/v4/middleware"
    "net/http"
)

func main() {
    e := echo.New()

    // 追加
    e.Use(middleware.Logger())

    e.GET("/", func(c echo.Context) error {
        return c.String(http.StatusOK, "Hello, World!")
    })
    e.Logger.Fatal(e.Start(":1323"))
}

このままでは必要な依存がまだ入っていないので、以下のコマンドを実行します。

$ go get -t .

サーバを再起動し、先ほどと同じようにcURLでアクセスすると今度はアクセスログが出力されることが確認できます。

$ go run server.go 

   ____    __
  / __/___/ /  ___
 / _// __/ _ \/ _ \
/___/\__/_//_/\___/ v4.6.1
High performance, minimalist Go web framework
https://echo.labstack.com
____________________________________O/_______
                                    O\
⇨ http server started on [::]:1323
{"time":"2021-10-15T08:44:10.73485721+09:00","id":"","remote_ip":"127.0.0.1","host":"localhost:1323","method":"GET","uri":"/","user_agent":"curl/7.68.0","status":200,"error":"","latency":7637,"latency_human":"7.637µs","bytes_in":0,"bytes_out":13}

デフォルトのログの設定は以下のようになっているみたいです。

DefaultLoggerConfig = LoggerConfig{
  Skipper: DefaultSkipper,
  Format: `{"time":"${time_rfc3339_nano}","id":"${id}","remote_ip":"${remote_ip}",` +
    `"host":"${host}","method":"${method}","uri":"${uri}","user_agent":"${user_agent}",` +
    `"status":${status},"error":"${error}","latency":${latency},"latency_human":"${latency_human}"` +
    `,"bytes_in":${bytes_in},"bytes_out":${bytes_out}}` + "\n",
  CustomTimeFormat: "2006-01-02 15:04:05.00000",
}

Request ID Middlewareを使う

Request ID Middlewareを使えばRequestに対してユニークなIDを割り振ることができます。
このミドルウェアはクライアント側がX-Request-IDのリクエストヘッダーを付けている場合そのIDを利用し、ない場合はデフォルトでrandom.String(32)を利用してIDを割り振ります。
本来は分散トレーシングがメインな理由で用いられるものかと推測していますが、このミドルウェアを利用しているとLogger MiddlewareでもRequest IDが出力れるようになりログを追うときに何かと便利です。

こちらも使い方は簡単で、以下のようにミドルウェアを追加します。

server.go

package main

import (
    "github.com/labstack/echo/v4"
    "github.com/labstack/echo/v4/middleware"
    "github.com/labstack/gommon/log"
    "net/http"
)

func main() {
    e := echo.New()

    // 追加
    e.Use(middleware.RequestID())

    e.Use(middleware.LoggerWithConfig(middleware.LoggerConfig{
        Format: "id=${id}, time=${time_rfc3339_nano}, method=${method}, uri=${uri}, status=${status}\n",
    }))

    e.Logger.SetLevel(log.INFO)
    e.Logger.Info("hello")

    e.GET("/", func(c echo.Context) error {
        return c.String(http.StatusOK, "Hello, World!")
    })

    e.Logger.Fatal(e.Start(":1323"))
}

サーバを再起動し、先ほどと同じようにcURLでアクセスすると今度はアクセスログにIDが含まれていることが確認できます。

# Request ID Middlewareを使っていない時
{"time":"2021-10-15T08:44:10.73485721+09:00","id":"","remote_ip":"127.0.0.1","host":"localhost:1323","method":"GET","uri":"/","user_agent":"curl/7.68.0","status":200,"error":"","latency":7637,"latency_human":"7.637µs","bytes_in":0,"bytes_out":13}

# Request ID Middlewareを使った時
{"time":"2021-10-15T09:09:08.795038871+09:00","id":"DIO17Vgnl1NN9sxnoZPDJNXiSf4o4p53","remote_ip":"127.0.0.1","host":"localhost:1323","method":"GET","uri":"/","user_agent":"curl/7.68.0","status":200,"error":"","latency":78319,"latency_human":"78.319µs","bytes_in":0,"bytes_out":13}

idの項目に値が入っているのを確認できます。
今度はX-Request-IDを付与して、リクエストを送ってみます。

$ curl -H "X-Request-ID: 12345" localhost:1323
Hello, World!

するとログ出力は以下のようになります。

{"time":"2021-10-15T09:26:56.894261759+09:00","id":"12345","remote_ip":"127.0.0.1","host":"localhost:1323","method":"GET","uri":"/","user_agent":"curl/7.68.0","status":200,"error":"","latency":43280,"latency_human":"43.28µs","bytes_in":0,"bytes_out":13}

X-Request-IDの値が入ってますね。

Loggerを使う

最後にEchoのLoggerを使ってみます。
これはEchoのインスタンスに生えています。
具体的には、以下のようにします。

package main

import (
    "github.com/labstack/echo/v4"
    "github.com/labstack/echo/v4/middleware"
    "github.com/labstack/gommon/log"
    "net/http"
)

func main() {
    e := echo.New()

    e.Use(middleware.RequestID())
    e.Use(middleware.Logger())

    // 追加
    if l, ok := e.Logger.(*log.Logger); ok {
        l.SetLevel(log.INFO)
    }

    e.GET("/", func(c echo.Context) error {
        // 追加
        e.Logger.Info("hello func is called")
        return c.String(http.StatusOK, "Hello, World!")
    })

    e.Logger.Fatal(e.Start(":1323"))
}

ポイントは、e.Logger.SetLevel(log.INFO)のところで、EchoのロガーはデフォルトでログレベルがERRORになるのでそれ以上のレベルのエラーを出力したい場合は明示的に設定してやる必要があります。

アプリを再起動してcURLを叩くと以下のようなログが出力されているのが確認できます。

{"time":"2021-10-15T12:26:21.21687368+09:00","level":"INFO","prefix":"echo","file":"server.go","line":"20","message":"hello func is called"}

この辺まだ理解が甘いところではあるのですが、おそらくレイヤリングの設計をしているアプリケーション内で使っていくにはEchoのコンテキストを引き回していくか、DIして使うのが基本的な感じになるかなと想像しています。（もっとよいやり方があればコメントとかで教えてくださると嬉しいです）

このロガーのフォーマットを変えたい場合はEcho#Logger.SetHeader(string)で行なうことができます。
例えば以下のように利用します。

func main() {
    e := echo.New()

    e.Use(middleware.RequestID())
    e.Use(middleware.Logger())

    if l, ok := e.Logger.(*log.Logger); ok {
        // 追加
        l.SetHeader("${time_rfc3339} ${level}")
        l.SetLevel(log.INFO)
    }


    e.GET("/", func(c echo.Context) error {
        // 追加
        e.Logger.Info("hello func is called")
        return c.String(http.StatusOK, "Hello, World!")
    })

    e.Logger.Fatal(e.Start(":1323"))
}

アプリを再起動してcURLを叩くと以下のようなログが出力されているのが確認できます。

2021-10-15T12:32:48+09:00 INFO hello func is called

ここで、利用できるタグが以下のものがあるみたいです。

time_rfc3339
time_rfc3339_nano
level
prefix
long_file
short_file
line

１つ１つは名前の通りなので説明はしませんが、大雑把な使い方は全体を通してこんな感じになってるみたいです。

へのへのもへじ

Echoのロガーを使う