nouhau icon indicating copy to clipboard operation
nouhau copied to clipboard

Stackdriver Traceを強制的に出力する

Open sinmetal opened this issue 6 years ago • 13 comments

WHAT

Stackdriver Traceを強制的に出力する方法

Google App Engine

App Engineの場合はリクエストヘッダーに "X-Cloud-Trace-Context: TRACE_ID/SPAN_ID;o=TRACE_TRUE" を追加することで、そのリクエストを強制的にトレースできる。

各値の説明とcurlのサンプルは以下の通り。

  • TRACE_ID は、128 ビットの番号を表す 32 文字の 16 進数値です。リクエストを束ねるつもりがないのであれば、リクエスト間で一意の値にする必要があります。これには UUID を使用できます。

  • SPAN_ID は、(符号なしの)スパン ID の 10 進表現です。トレースの最初のスパンでは 0 にする必要があります。後続のリクエストでは、SPAN_ID を親リクエストのスパン ID に設定します。ネストしたトレースについて詳しくは、TraceSpan(REST、RPC)の説明をご覧ください。

  • このリクエストをトレースするには、TRACE_TRUE を 1 に設定する必要があります。リクエストをトレースしない場合は 0 を指定します。

curl "http://www.example.com" --header "X-Cloud-Trace-Context:105445aa7843bc8bf206b120001000/0;o=1"

Refs

  • https://cloud.google.com/trace/docs/troubleshooting#force-trace

Client Library

TraceのStartSpan時にサンプリングの設定を追加できる。 Goの場合は https://godoc.org/go.opencensus.io/trace#AlwaysSample を設定すれば、必ず出力される。

ctx, span := trace.StartSpan(ctx, "/process", trace.WithSampler(trace.AlwaysSample()))
defer span.End()

WHY

  • サンプリングしてTraceに出力されるので、リクエストの間隔が長いと、全然出力されないことがある。
  • 10sec毎にループで回してたりすると、ほぼ出てこない。
  • 開発環境は自分でたくさんリクエストを起こすのがめんどい。

sinmetal avatar Oct 28 '18 05:10 sinmetal

"X-Cloud-Trace-Context: TRACE_ID/SPAN_ID;o=TRACE_TRUE" はApp Engine以外も行ける気がするけど、コードをどういうふうにしておけば、できるのかはまだ試してない。

sinmetal avatar Oct 28 '18 05:10 sinmetal

X-Cloud-Trace-Context は元々 Stackdriver Trace 用に Google Frontend が付与していたヘッダーが OpenCensus で標準的に使われるようになっているもので、 OpenCensus 使っているなら App Engine 以外でも Go 以外でも同じですね。

ここに書かれているかと思ったらまだ書かれていなかった https://opencensus.io/advanced-concepts/context-propagation/ このあたりで実装 https://github.com/search?q=org%3Acensus-instrumentation+x-cloud-trace-context&type=Code

apstndb avatar Oct 28 '18 05:10 apstndb

Server側はrequest.Context()からStartSpanしてればいい・・・?

package main

import (
	"fmt"
	"log"
	"net/http"
	"time"

	"contrib.go.opencensus.io/exporter/stackdriver"
	"go.opencensus.io/plugin/ochttp"
	"go.opencensus.io/trace"
)

func main() {
	// Create and register a OpenCensus Stackdriver Trace exporter.
	exporter, err := stackdriver.NewExporter(stackdriver.Options{
		ProjectID: "metal-tile-dev1",
	})
	if err != nil {
		log.Fatal(err)
	}
	trace.RegisterExporter(exporter)

	http.HandleFunc("/", handler)
	log.Fatal(http.ListenAndServe(":8080", &ochttp.Handler{}))
}

func handler(w http.ResponseWriter, r *http.Request) {
	ctx := r.Context()
	ctx, span := trace.StartSpan(ctx, "/backendhellotime")
	defer span.End()

	fmt.Fprintf(w, "Hello Backend %s", time.Now())
}

sinmetal avatar Oct 28 '18 06:10 sinmetal

あとは他のマイクロサービスにリクエストするときにはちゃんと ochttp.Transport を使うとかですかね https://cloud.google.com/trace/docs/setup/go#wzxhzdk12wzxhzdk13sample_product_name_application_for_go

apstndb avatar Oct 28 '18 06:10 apstndb

おらおらーって書いたら、できたー! ただ、謎の Recv./ ってのが出るのはなんでなのかあんまりよく分かっていない。

image

package main

import (
	"fmt"
	"log"
	"net/http"
	"time"

	"contrib.go.opencensus.io/exporter/stackdriver"
	"contrib.go.opencensus.io/exporter/stackdriver/propagation"
	"go.opencensus.io/plugin/ochttp"
	"go.opencensus.io/trace"
)

func main() {
	projectID, err := GetProjectID()
	if err != nil {
		panic(err)
	}
	// Create and register a OpenCensus Stackdriver Trace exporter.
	exporter, err := stackdriver.NewExporter(stackdriver.Options{
		ProjectID: projectID,
	})
	if err != nil {
		log.Fatal(err)
	}
	trace.RegisterExporter(exporter)

	trace.ApplyConfig(trace.Config{DefaultSampler: trace.AlwaysSample()}) // defaultでは10,000回に1回のサンプリングになっているが、リクエストが少ないと出てこないので、とりあえず全部出す

	server := &http.Server{
		Addr: ":8080",
		Handler: &ochttp.Handler{
			Handler:     http.DefaultServeMux,
			Propagation: &propagation.HTTPFormat{},
		},
	}

	http.HandleFunc("/", handler)
	if err := server.ListenAndServe(); err != nil {
		log.Fatal(err)
	}
}

func handler(w http.ResponseWriter, r *http.Request) {
	ctx := r.Context()
	ctx, span := trace.StartSpan(ctx, "/backendhellotime")
	defer span.End()

	fmt.Fprintf(w, "Hello Backend %s", time.Now())
}

sinmetal avatar Oct 29 '18 09:10 sinmetal

http.HandleFunc("/", handler)

/ では。

多分 ochttp.WithRouteTag とかかぶせるやつ https://godoc.org/go.opencensus.io/plugin/ochttp#hdr-Tracing

apstndb avatar Oct 29 '18 09:10 apstndb

基本的な設計としては instrumentation は各言語のフレームワーク/ライブラリに合ったものが標準で用意されているので適切に使うのであればプリミティブとしての trace.StartSpan は使わなくても span が設定されるようになっているはずですね。(この場合 net/http) https://github.com/census-instrumentation/opencensus-go#getting-started

apstndb avatar Oct 29 '18 09:10 apstndb

よっしゃ!と思って書いたけど、微妙に思ったとおりにならなかった。

image

http.Handle("/", ochttp.WithRouteTag(func() http.Handler { return http.HandlerFunc(handler) }(), "/backendhellotime/"))
	if err := server.ListenAndServe(); err != nil {
		log.Fatal(err)
	}

sinmetal avatar Oct 29 '18 09:10 sinmetal

formatSpanName指定すればいけるんじゃないかと思ったけど、分かりやすくなったけど、ちょっと違う感じになったw

image

func main() {
	projectID, err := GetProjectID()
	if err != nil {
		panic(err)
	}
	// Create and register a OpenCensus Stackdriver Trace exporter.
	exporter, err := stackdriver.NewExporter(stackdriver.Options{
		ProjectID: projectID,
	})
	if err != nil {
		log.Fatal(err)
	}
	trace.RegisterExporter(exporter)

	trace.ApplyConfig(trace.Config{DefaultSampler: trace.AlwaysSample()}) // defaultでは10,000回に1回のサンプリングになっているが、リクエストが少ないと出てこないので、とりあえず全部出す

	server := &http.Server{
		Addr: ":8080",
		Handler: &ochttp.Handler{
			Handler:        http.DefaultServeMux,
			Propagation:    &propagation.HTTPFormat{},
			FormatSpanName: formatSpanName,
		},
	}

	http.Handle("/", ochttp.WithRouteTag(func() http.Handler { return http.HandlerFunc(handler) }(), "/backendhellotime/"))
	if err := server.ListenAndServe(); err != nil {
		log.Fatal(err)
	}
}

func handler(w http.ResponseWriter, r *http.Request) {
	fmt.Fprintf(w, "Hello Backend %s", time.Now())
}

func formatSpanName(r *http.Request) string {
	return fmt.Sprintf("/backendhellotime%s", r.URL.Path)
}

sinmetal avatar Oct 29 '18 09:10 sinmetal

そもそもどう表示してほしいのかがよくわからんという気持ちに。実際にアクセスするパスは /backendhellotime じゃないんですよね

apstndb avatar Oct 29 '18 10:10 apstndb

Recv. ってのが何なんだろう?ってずっと悩んでたけど、通りがかりの人が、 SpanKindがServerだと Recv. で、Clientだと Sent. なんじゃないか?と言われて、なるほど!!!って気持ちになって解決した・・・!

sinmetal avatar Oct 29 '18 10:10 sinmetal

分散トレーシングに関しては理屈はこの発表のときに説明をしたんだけれども、需要がありそうならブログ記事書こうと思ってたので書きます。 http://bit.ly/20180923-student-go-trace

ymotongpoo avatar Oct 29 '18 13:10 ymotongpoo

先週ぐらいにこの記事を見たかったw

sinmetal avatar Oct 29 '18 13:10 sinmetal