Article:

近年、ソフトウェア開発におけるObservability（観測性）の重要性が一層高まっていますよね(肌感)。

私個人の開発としても、HTTPリクエストのデバッグにトレースが活用しています。トレースを使うことで、エラーが発生した具体的な箇所が明確になり、ログを頼りに推測する手間が省けます。

また、ユーザーから「エラーが出た」と報告を受けた際、フロントエンドで表示されるtraceIDを教えてもらうことで、迅速にバグ修正に取り掛かることが可能です。

しかし、トレースを見るためには専用の環境が必要です。トレースに依存しすぎてログの出力を減らしてしまうと、ローカル開発環境では何が起こっているのか把握しづらくなるという問題もあります。

そこで最近、私個人なりに今回はDocker Composeを用いてGrafana、Prometheus、Loki、Tempoをローカル環境で立ち上げ、本番環境と同じダッシュボードを使える開発環境をぼちぼち整えていたのですが、一通りまとまったかなといったところなのでサンプルとしてまとめ、公開・解説してみようと思います。

あくまでも私個人が試行錯誤した結果なので、もっと便利な方法があるかもしれません。一例として受け取っていただければ幸いです。

フォルダ構成をガチガチにしてもよかったのですが、今回はテンプレートではなくサンプルということでベタっと置いてあります。

サンプルプロジェクト

こちらで公開しています。

https://github.com/totegamma/go-lgtm-sample

最初に、dockerにlokiプラグインをインストールする必要があります。

1

docker plugin install grafana/loki-docker-driver:latest --alias loki --grant-all-permissions

このプラグインを使うこととで、標準出力のログをlokiに送信してくれます。k8sにデプロイするアプリケーションでは通常ログを標準出力に出すことが多いと思うので、必須のプラグインですね。

このプラグインがインストールできたら、docker compose upコマンドで立ち上げます。

立ち上がれば、localhost:3000でgrafanaが見れるようになるはずです。

サンプルとして組み込みのダッシュボードbasicが追加してあります。このようによく使うダッシュボードのjsonを組み込んでおくと便利ですね。

サンプルのアプリケーションとして、次の2つのAPIが実装してあります

  • GET: /wait ランダムな秒数遅延するだけのAPI
  • POST: /calc 四則演算の計算木となるjsonを受け取り、計算結果を返す謎のAPI

以下に、本サンプルの見どころをざっくりとまとめています。それぞれの見出し間はできるだけ独立させているので、気になるところだけ読んでみてください。

trace活用ハンズオン

/calc APIにリクエストを送って、1+1を計算させてみます。このとき、iオプションをつけてレスポンスヘッダも表示するようにしておきます。

1
2
3
4
5
6
7
8
9

> 09/01 17:42 ~$ curl -X"POST" -H"content-type: application/json" localhost:8000/calc -d '{"op": "+", "a": 1, "b": 1}' -i
HTTP/1.1 200 OK
Content-Type: application/json
Trace-Id: 5fbd6acdef6ab11d727d9f0769fc3bec
Date: Sun, 01 Sep 2024 08:42:47 GMT
Content-Length: 13

{"result":2}
> 09/01 17:42 ~$

result: 2で正しく計算できていることはどうでもよくて、今回の主役はレスポンスヘッダのTrace-Id: 5fbd6acdef6ab11d727d9f0769fc3becです。

grafanaのexplorerビューでこれを検索してみましょう。

このように、特定のAPIリクエストのトレースを素早く検査することができました。

次に、エラーになるリクエストも送ってみましょう。ゼロ除算が起こる計算木を渡してみます。

1
2
3
4
5
6
7
8
9

> 09/01 17:45 ~$ curl -X"POST" -H"content-type: application/json" localhost:8000/calc -d '{"op": "/", "a": 30, "b": {"op": "-", "a": 10, "b": 10}}' -i
HTTP/1.1 400 Bad Request
Content-Type: application/json
Trace-Id: ea485b6248b0f15a170c83bc1d97f288
Date: Sun, 01 Sep 2024 08:45:22 GMT
Content-Length: 29

{"error":"division by zero"}
> 09/01 17:45 ~$

400が帰ってきてますね。 grafanaで見てみると、次のようなトレースになっており、2回呼ばれているcalcのうち、上位にあるものがエラーになっていることが素早くわかります。

また、attributesを見てみると、A=30, B=0, operation="/"となっており、たしかに0除算がここで発生していることが確信できます。

ログの確認

explorerビューでDatasourceとしてlokiを指定し、compose_serviceラベルにログを見たいdocker composeのサービス名を指定することで、そのサービスのログを確認できます。

今回はappコンテナしかありませんが、マイクロサービスの開発などで複数サービスがある場合、このクエリを切り替えつつログを確認することができます。

トレースIDをHTTPレスポンスヘッダーに含める

echoのミドルウェアで実装します。otelechoのセットアップより後に挿入しないとtraceIDが取れないのでそこだけ注意です。

1
2
3
4
5
6
7

e.Use(func(next echo.HandlerFunc) echo.HandlerFunc {
    return func(c echo.Context) error {
        span := trace.SpanFromContext(c.Request().Context())
        c.Response().Header().Set("trace-id", span.SpanContext().TraceID().String())
        return next(c)
    }
})

また、多くの場合webフロントエンドでtraceIDを受け取るために、corsの設定が必要になるかと思います。

1
2
3
4

e.Use(middleware.CORSWithConfig(middleware.CORSConfig{
    ...
    ExposeHeaders: []string{"trace-id"},
}))

アプリコンテナのホットリロード

アプリケーションはコンテナの内部で動かすようにしてみました。

また、内部ではairを使っていて、ソースを書き換えると自動で再コンパイル・再起動が行われるようになっています。

別にコンテナにいれる必要はなくて、手元でそのままairを実行してもよかったのですが、今回のcomposeの方針としてできるだけポートを外部にさらしすぎないようにしていて、tempoやprometheusに外部からアクセスできないためコンテナ内部に閉じ込めるようにしてみました。

Grafanaのセットアップ

いちいちログインするのは大変面倒なので、環境変数で認証無しでログインできるように設定しています。

compose.yml
1
2
3
4

environment:
    - GF_AUTH_ANONYMOUS_ENABLED=true
    - GF_AUTH_ANONYMOUS_ORG_ROLE=Admin
    - GF_AUTH_DISABLE_LOGIN_FORM=true

また、データソース・ダッシュボードもあらかじめ設定ファイルをyamlで生成し、読み込むように設定しておくことで、立ち上げてすぐいつものダッシュボードを開くことができます。

Logs to Trace, Trace to Logs

トレースとログのエントリーに、対応するログ・トレースにジャンプするボタンが追加されています。

詳細は過去記事slogでログにTraceIDを出す とGoプログラムのトレースを取ってGrafanaCloudで可視化するを参照してください。

今回の新しい点としては、過去記事でGrafanaのwebUIで行っていた一部の設定をyamlで記載する必要があります。_dev/grafana-datasources.yamlにjsonDataとしてtraceToLogsV2及びderivedFieldsの設定が行われているので、そこを確認してみてください。

テストでのトレースの確認

ローカル開発環境でも便利にトレースが見れるようにはなりましたが、問題になるのはテストです。テストでも、呼び出し先の関数で何が起こったのかを知りたいですよね。

本サンプルでは、ダミーのトレースプロバイダーと、簡易的なトレースの表示関数を用意してみました。go test .を実行すると以下が表示されるはずです(あえて失敗するテストにしてあります)。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38

[totegamma@16:22].../git/go-lgtm-sample$ go test .
--- FAIL: TestCalcInvalidInput (0.00s)
    main_test.go:53:
                Error Trace:    /home/totegamma/git/go-lgtm-sample/main_test.go:53
                Error:          Received unexpected error:
                                division by zero
                                app.Calc
                                        /home/totegamma/git/go-lgtm-sample/calc.go:100
                                app.TestCalcInvalidInput
                                        /home/totegamma/git/go-lgtm-sample/main_test.go:52
                                testing.tRunner
                                        /home/totegamma/.asdf/installs/golang/1.22.5/go/src/testing/testing.go:1689
                                runtime.goexit
                                        /home/totegamma/.asdf/installs/golang/1.22.5/go/src/runtime/asm_amd64.s:1695
                Test:           TestCalcInvalidInput
    dummyTracer.go:60: ---- 9e92d9aa224c0721e601d4ba5b6dbacd ----
    dummyTracer.go:75: Name: Calc
    dummyTracer.go:76: Attributes:
    dummyTracer.go:78:   operation: STRING: -
    dummyTracer.go:78:   A: FLOAT64: 1.000000
    dummyTracer.go:78:   B: FLOAT64: 1.000000
    dummyTracer.go:80: Events:
    dummyTracer.go:87: --------------------------------
    dummyTracer.go:75: Name: Calc
    dummyTracer.go:76: Attributes:
    dummyTracer.go:78:   operation: STRING: /
    dummyTracer.go:78:   A: FLOAT64: 1.000000
    dummyTracer.go:78:   B: FLOAT64: 0.000000
    dummyTracer.go:80: Events:
    dummyTracer.go:82:   exception
    dummyTracer.go:84:     exception.type: STRING: *errors.fundamental
    dummyTracer.go:84:     exception.message: STRING: division by zero
    dummyTracer.go:87: --------------------------------
FAIL
FAIL    app     0.008s
FAIL
Exit status: 1
[totegamma@16:22].../git/go-lgtm-sample$

トレース内部のAttributes, Eventsがプリントされています。 これで、関数呼び出しのどこでエラーが発生したのか、その時のパラメーターが何だったのかが、簡単に追跡できます。

関連関数はinternal/testutil/dummyTracer.goに記載してあります。

負荷試験との組み合わせ

負荷試験ツールであるk6のコンテナをcomposeに含めており、簡単に負荷試験が実施できるようになっています。 サンプルでの負荷試験のシナリオの格納場所は_dev/k6です。

とはいえローカルでグラフを見て性能を測ることはいうてないとは思いますが、負荷試験のシナリオを設計する際は便利なのではないのでしょうか。

1

docker compose run --rm k6 run /scripts/loadtest.js

k6からのメトリクスやログもprometheus/lokiに送信するように環境変数が設定されており、実行するとbasicダッシュボードで確認できます。

おわりに

本記事では私の個人的なローカル開発環境をいくらかサンプルという形でまとめて公開し、いくつかの項目について解説しました。

個人的には何かとGrafanaのデータソースやダッシュボード周りをyamlで定義しておくのが地味にめんどくさかったので、こうしてplug and playで動くサンプルというのは何かと便利なんじゃないかな～とは思っています。ご活用いただければ幸いです。

みなさんも「これ便利だよ！」みたいなのがあればぜひぜひ教えていただけると嬉しいです。