Stackdriver Traceを強制的に出力する

[sinmetal]

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]

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

[apstndb]

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

[sinmetal]

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())
}

[apstndb]

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

[sinmetal]

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

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())
}

[apstndb]

http.HandleFunc("/", handler)

の / では。

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

[apstndb]

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

[sinmetal]

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

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

[sinmetal]

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

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)
}

[apstndb]

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

[sinmetal]

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

[ymotongpoo]

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

[sinmetal]

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