【Golang】Sentryの実装と並列実行対応

概要

弊社ではエラー監視としてsentryを使用しています。
golangでsentryを実装していく中で、詰まった箇所がなどがあったので備忘として残しておきます。
sentryの導入などを考えている方、カスタマイズやスレッドセーフな実装をしたい方に参考になればと思います。

前提環境

• Go v1.17
• github.com/getsentry/sentry-go v0.11.0

はじめに

まずはとくにかくgolangのサーバーの中のエラーを発生させて、sentryに通知させてみます。
サーバー起動の記述は省略して、sentryへの通知の記述だけ記載します。

sentry.go
scope.SetLevel(sentry.LevelError)でsentryのログレベルを設定、
sentry.CaptureException(err)でsentryにエラー内容を送信しています。

func PushSentry(err error) {
	sentry.ConfigureScope(func(scope *sentry.Scope) {
		scope.SetLevel(sentry.LevelError)
	})
	sentry.CaptureException(err)
}

health_check_service.go

func (hcs HealthCheckService) Check(ctx context.Context, req *health.HealthCheckRequest) (*health.HealthCheckResponse, error) {
	err := errors.New("test!")
	middleware.PushSentry(err)

	return &health.HealthCheckResponse{
		Status: health.HealthCheckResponse_SERVING,
	}, nil
}

実際に動かしてみると、sentryに届いていることが確認できます。

sentryログにリクエストパラメータを追加する

今のままではエラーの情報が少なく、障害調査が難しいです。
そこで、リクエストパラメータをsentryに送信できるようにしました。

sentry.go
scope.SetLevel(sentry.LevelError)でsentryのログレベルを設定、
sentry.CaptureException(err)でsentryにエラー内容を送信しています。

func PushSentry(err error, params interface{}) {
	sentry.ConfigureScope(func(scope *sentry.Scope) {
		if params != nil {
			scope.SetExtra("Request Params", params)
		}

		scope.SetLevel(sentry.LevelError)
	})
	sentry.CaptureException(err)
}

この状態でsentryに通知を行うとADDITIONAL DATAにリクエストパラメータが追加されます。

sentryログにtrackingIDを追加する

ここまで実装をしてみると、サーバーで標準出力しているログと、sentryのログとの紐付きが今のままではわからないということに気づきました。
サーバーで出力しているログは下記のようなものです。

{"level":"info","timestamp":"2022-06-27T12:31:18.593Z","caller":"middleware/logger.go:122","msg":"request start","tracking_id":"sakura-cl4wpy6v4000069mtutz7bcva","grpc.start_time":"2022-06-27T12:31:18.5924103Z","req":"service:\"sentry_test\""}
{"level":"info","timestamp":"2022-06-27T12:31:18.601Z","caller":"middleware/logger.go:148","msg":"request end","tracking_id":"sakura-cl4wpy6v4000069mtutz7bcva","grpc.end_time":"2022-06-27T12:31:18.6004953Z","grpc.duration_nano":8282833,"grpc.code":"OK","resp":"status:SERVING"}

そこで、sentryにtrackingIDのパラメータを追加しました。
trackingIDはcontxtに埋め込むようにしているので、そこから取得してsentryのログに渡しています。

func PushSentry(ctx context.Context, err error, params interface{}) {
	sentry.ConfigureScope(func(scope *sentry.Scope) {
		if params != nil {
			scope.SetExtra("Request Params", params)
		}

		trackingID := TrackingIDFromCtx(ctx)
		scope.SetExtra("Tracking ID", trackingID)
		scope.SetLevel(sentry.LevelError)
	})
	sentry.CaptureException(err)
}

これでsentryにpushするとtrackingIDが確認できました。

スレッドセーフにする

一通り実装したため、本番を想定して同時にリクエストを送ってみました。
結果が下記です。

標準出力

{"level":"info","timestamp":"2022-06-27T15:39:53.549Z","caller":"middleware/logger.go:126","msg":"request start","tracking_id":"cl4wwopjf0000asmtsa6bj0bk","grpc.start_time":"2022-06-27T15:39:53.547778679Z","req":"service:\"sentry_test:B\""}
{"level":"info","timestamp":"2022-06-27T15:39:53.549Z","caller":"middleware/logger.go:126","msg":"request start","tracking_id":"cl4wwopjf0002asmth043751r","grpc.start_time":"2022-06-27T15:39:53.547893471Z","req":"service:\"sentry_test:C\""}
{"level":"info","timestamp":"2022-06-27T15:39:53.549Z","caller":"middleware/logger.go:126","msg":"request start","tracking_id":"cl4wwopjf0001asmtt0ub475t","grpc.start_time":"2022-06-27T15:39:53.547744346Z","req":"service:\"sentry_test:A\""}
{"level":"info","timestamp":"2022-06-27T15:39:53.699Z","caller":"middleware/logger.go:152","msg":"request end","tracking_id":"cl4wwopjf0002asmth043751r","grpc.end_time":"2022-06-27T15:39:53.698990221Z","grpc.duration_nano":151106667,"grpc.code":"OK","resp":"status:SERVING"}
{"level":"info","timestamp":"2022-06-27T15:39:53.699Z","caller":"middleware/logger.go:152","msg":"request end","tracking_id":"cl4wwopjf0001asmtt0ub475t","grpc.end_time":"2022-06-27T15:39:53.698902805Z","grpc.duration_nano":151196459,"grpc.code":"OK","resp":"status:SERVING"}
{"level":"info","timestamp":"2022-06-27T15:39:53.699Z","caller":"middleware/logger.go:152","msg":"request end","tracking_id":"cl4wwopjf0000asmtsa6bj0bk","grpc.end_time":"2022-06-27T15:39:53.698921888Z","grpc.duration_nano":151596001,"grpc.code":"OK","resp":"status:SERVING"}

setnryログ

トラッキングIDとリクエストパラムの値が、標準出力とsentryのログで噛み合っていないのがわかるかと思います。
つまり、この実装ではスレッドセーフにできていないことに気づきました。
(ちなみに前提として、標準出力のログの方は問題なくスレッドセーフにできています。)

そこでsentryのドキュメントを再度読み直しました

Concurrent Go programs use goroutines, a form of lightweight thread managed by the Go runtime. Because goroutines run concurrently, every goroutine has to keep track of its own Sentry-related data locally. Otherwise, data races can introduce subtle bugs to your programs, and the consequences vary from nothing apparent to unexpected crashes or, worse, accidentally mixing up data stored in the Scope. More on this in the Scopes and Hubs section.

つまり、goroutineごとにsentryのデータを保持することで並行処理への対応ができるということのようです。
そのための概念としてscopeとhubがあります。

What's a Scope, What's a Hub
You can think of the hub as the central point that our SDKs use to route an event to Sentry. When you call init() a hub is created and a client and a blank scope are created on it. That hub is then associated with the current thread and will internally hold a stack of scopes.
The scope will hold useful information that should be sent along with the event. For instance contexts or breadcrumbs are stored on the scope. When a scope is pushed, it inherits all data from the parent scope and when it pops all modifications are reverted.
The default SDK integrations will push and pop scopes intelligently. For instance web framework integrations will create and destroy scopes around your routes or controllers.

hubとは

• sentryへpushするための中継地点のようなもの
• スレッドごと(goでいうとgoroutine)に関連づけられる
• 内部にはscopeの情報を持つ

scopeとは

• sentryへpushするための情報を格納する
• 例えばcontextやりくえすとパラメータなど

以上を踏まえると、goroutineごとにhubを生成して、その中でscopeの設定をすればスレッドセーフな実装ができそうです。
再度ドキュメントに戻り、実装例を参考に修正を施しました。

func PushSentry(ctx context.Context, err error, params interface{}) {
	hub := sentry.CurrentHub().Clone()
	hub.ConfigureScope(func(scope *sentry.Scope) {
		if params != nil {
			scope.SetExtra("Request Params", params)
		}

		trackingID := TrackingIDFromCtx(ctx)
		//fmt.Println("trackingID:", trackingID)
		scope.SetExtra("Tracking ID", trackingID)
		scope.SetLevel(sentry.LevelError)
	})
	hub.CaptureException(err)
}

実際に同時リクエストを送ってみると

標準出力

{"level":"info","timestamp":"2022-06-27T15:49:34.008Z","caller":"middleware/logger.go:125","msg":"request start","tracking_id":"cl4wx15fb000261mtd4dryztc","grpc.start_time":"2022-06-27T15:49:34.007917337Z","req":"service:\"sentry_test:C\""}
{"level":"info","timestamp":"2022-06-27T15:49:34.008Z","caller":"middleware/logger.go:125","msg":"request start","tracking_id":"cl4wx15fb000061mt02zzn16c","grpc.start_time":"2022-06-27T15:49:34.007846712Z","req":"service:\"sentry_test:B\""}
{"level":"info","timestamp":"2022-06-27T15:49:34.008Z","caller":"middleware/logger.go:125","msg":"request start","tracking_id":"cl4wx15fb000161mtos4mck8k","grpc.start_time":"2022-06-27T15:49:34.008056753Z","req":"service:\"sentry_test:A\""}
{"level":"info","timestamp":"2022-06-27T15:49:34.040Z","caller":"middleware/logger.go:151","msg":"request end","tracking_id":"cl4wx15fb000061mt02zzn16c","grpc.end_time":"2022-06-27T15:49:34.040125212Z","grpc.duration_nano":32288292,"grpc.code":"OK","resp":"status:SERVING"}
{"level":"info","timestamp":"2022-06-27T15:49:34.040Z","caller":"middleware/logger.go:151","msg":"request end","tracking_id":"cl4wx15fb000261mtd4dryztc","grpc.end_time":"2022-06-27T15:49:34.040072712Z","grpc.duration_nano":32168667,"grpc.code":"OK","resp":"status:SERVING"}
{"level":"info","timestamp":"2022-06-27T15:49:34.040Z","caller":"middleware/logger.go:151","msg":"request end","tracking_id":"cl4wx15fb000161mtos4mck8k","grpc.end_time":"2022-06-27T15:49:34.040046045Z","grpc.duration_nano":32017042,"grpc.code":"OK","resp":"status:SERVING"}

setnryログ

標準出力のトラッキングID、リクエストパラメータの組み合わせと、sentryログのトラッキングID、リクエストパラメータの組み合わせが一致していることがわかるかと思います。

さいごに

トレタでは一緒に開発する仲間を募集しています。

興味がある方は是非カジュアル面談へお越しください！