How do I get the trace.id of apmgrpc in gRPC?

[EDDYCJY (JianYu)]

I want to get the apm trace.id of the currently called method in the gRPC Interceptor. How can I get it?

func TestInterceptor(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
	resp, rerr := handler(ctx, req)
    // How to get apm trace.id here...
	return resp, rerr
}

Kibana APM:

We want to record each trace.id so that we can accurately query a request link on Kibana APM.

[axw (Andrew Wilkins)]

@EDDYCJY welcome to the forum!

You can use apm.TransactionFromContext to get the transaction from ctx, and then call the transaction's TraceContext method. The result is an apm.TraceContext, which contains a Trace field. The Trace field's String() method will return the hex format like in the screenshot you provided.

You might like to use apmlogrus.TraceContext as an example.

May I ask why you want the trace ID? For logging?

[EDDYCJY (JianYu)]

@axw Thanks for the reply, I still can't get a valid value after configuring according to the guidelines. as follows:

func TestInterceptor(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
	resp, err := handler(ctx, req)

    log.Printf("interceptor.ctx: %+v", ctx)

	tx := apm.TransactionFromContext(ctx)
	traceContext := tx.TraceContext()
	
	log.Printf("trace.id: %s", traceContext.Trace.String())

	return resp, err
}

AServiceMethod Log output:

2019/03/22 14:38:55 interceptor.ctx: context.Background.WithCancel.WithValue(&http.contextKey{name:"local-addr"}, &net.TCPAddr{IP:net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0x7f, 0x0, 0x0, 0x1}, Port:10002, Zone:""}).WithValue(&http.contextKey{name:"http-server"}, &http.Server{Addr:":10002", Handler:(http.HandlerFunc)(0x46c1990), TLSConfig:(*tls.Config)(0xc00007e780), ReadTimeout:0, ReadHeaderTimeout:0, WriteTimeout:0, IdleTimeout:0, MaxHeaderBytes:0, TLSNextProto:map[string]func(*http.Server, *tls.Conn, http.Handler){"h2":(func(*http.Server, *tls.Conn, http.Handler))(0x42d4420)}, ConnState:(func(net.Conn, http.ConnState))(nil), ErrorLog:(*log.Logger)(nil), disableKeepAlives:0, inShutdown:0, nextProtoOnce:sync.Once{m:sync.Mutex{state:0, sema:0x0}, done:0x1}, nextProtoErr:error(nil), mu:sync.Mutex{state:0, sema:0x0}, listeners:map[*net.Listener]struct {}{(*net.Listener)(0xc0002efba0):struct {}{}}, activeConn:map[*http.conn]struct {}{(*http.conn)(0xc0001da0a0):struct {}{}, (*http.conn)(0xc000290000):struct {}{}}, doneChan:(chan struct {})(nil), onShutdown:[]func(){(func())(0x42dd400)}}).WithCancel.WithCancel.WithValue(metadata.mdIncomingKey{}, metadata.MD{"user-agent":[]string{"grpc-go/1.14.0"}, "grpcgateway-user-agent":[]string{"PostmanRuntime/7.1.1"}, "grpcgateway-accept":[]string{"*/*"}, "content-type":[]string{"application/grpc"}, ":authority":[]string{"grpc-server"}, "x-forwarded-host":[]string{"127.0.0.1:10002"}, "x-forwarded-for":[]string{"127.0.0.1"}, "grpcgateway-cache-control":[]string{"no-cache"}}).WithValue(peer.peerKey{}, &peer.Peer{Addr:"127.0.0.1:58810", AuthInfo:credentials.TLSInfo{State:tls.ConnectionState{Version:0x303, HandshakeComplete:true, DidResume:false, CipherSuite:0xc02b, NegotiatedProtocol:"h2", NegotiatedProtocolIsMutual:true, ServerName:"grpc-server", PeerCertificates:[]*x509.Certificate(nil), VerifiedChains:[][]*x509.Certificate(nil), SignedCertificateTimestamps:[][]uint8(nil), OCSPResponse:[]uint8(nil), ekm:(func(string, []uint8, int) ([]uint8, error))(0x42390f0), TLSUnique:[]uint8{0x42, 0x26, 0xe7, 0x76, 0x25, 0xc, 0xd5, 0x29, 0xdf, 0xbc, 0x4c, 0x2a}}}}).WithValue(grpc.streamKey{}, <stream: 0xc000504200, /kibana.KibanaService2/Get>)
2019/03/22 14:38:55 trace.id: 00000000000000000000000000000000

BServiceMethod Log output:

2019/03/22 14:38:55 interceptor.ctx: context.Background.WithCancel.WithValue(&http.contextKey{name:"local-addr"}, &net.TCPAddr{IP:net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0x7f, 0x0, 0x0, 0x1}, Port:10003, Zone:""}).WithValue(&http.contextKey{name:"http-server"}, &http.Server{Addr:":10003", Handler:(http.HandlerFunc)(0x46bd380), TLSConfig:(*tls.Config)(0xc000001c80), ReadTimeout:0, ReadHeaderTimeout:0, WriteTimeout:0, IdleTimeout:0, MaxHeaderBytes:0, TLSNextProto:map[string]func(*http.Server, *tls.Conn, http.Handler){"h2":(func(*http.Server, *tls.Conn, http.Handler))(0x42d3ff0)}, ConnState:(func(net.Conn, http.ConnState))(nil), ErrorLog:(*log.Logger)(nil), disableKeepAlives:0, inShutdown:0, nextProtoOnce:sync.Once{m:sync.Mutex{state:0, sema:0x0}, done:0x1}, nextProtoErr:error(nil), mu:sync.Mutex{state:0, sema:0x0}, listeners:map[*net.Listener]struct {}{(*net.Listener)(0xc000519b90):struct {}{}}, activeConn:map[*http.conn]struct {}{(*http.conn)(0xc0000b5f40):struct {}{}, (*http.conn)(0xc00025c0a0):struct {}{}}, doneChan:(chan struct {})(nil), onShutdown:[]func(){(func())(0x42dcfd0)}}).WithCancel.WithCancel.WithValue(metadata.mdIncomingKey{}, metadata.MD{":authority":[]string{"grpc-server"}, "user-agent":[]string{"grpc-go/1.14.0"}, "elastic-apm-traceparent":[]string{"00-357634f4db3f5be9540d7197dc0a5034-fe0e14743dcd94b9-01"}, "content-type":[]string{"application/grpc"}}).WithValue(peer.peerKey{}, &peer.Peer{Addr:"127.0.0.1:58816", AuthInfo:credentials.TLSInfo{State:tls.ConnectionState{Version:0x303, HandshakeComplete:true, DidResume:false, CipherSuite:0xc02b, NegotiatedProtocol:"h2", NegotiatedProtocolIsMutual:true, ServerName:"grpc-server", PeerCertificates:[]*x509.Certificate(nil), VerifiedChains:[][]*x509.Certificate(nil), SignedCertificateTimestamps:[][]uint8(nil), OCSPResponse:[]uint8(nil), ekm:(func(string, []uint8, int) ([]uint8, error))(0x4238cc0), TLSUnique:[]uint8{0x4f, 0xe1, 0x5c, 0x2c, 0x3f, 0x3b, 0xff, 0x24, 0xea, 0x31, 0xce, 0x0}}}}).WithValue(grpc.streamKey{}, <stream: 0xc0005e6000, /kibana.KibanaService3/Get>)
2019/03/22 14:38:55 trace.id: 00000000000000000000000000000000

My test scenario is to call the RPC method of the A service, and it will internally call the RPC method of the B service.

In the interceptor of the A service, ctx does not find the value associated with apm, and the trace.id is 0. In the interceptor of the B service, although there is an apm related value in ctx, the trace.id is still 0.

[EDDYCJY (JianYu)]

The purpose of logging trace.id is to concatenate each request with the relevant data in APM.

[axw (Andrew Wilkins)]

@EDDYCJY

@axw Thanks for the reply, I still can't get a valid value after configuring according to the guidelines.

How are you registering the interceptor? You need to make sure your interceptor is run after the apmgrpc interceptor. e.g.

grpc.NewServer(grpc_middleware.WithUnaryServerChain(
    apmgrpc.NewUnaryServerInterceptor(),
    TestInterceptor,
))

The purpose of logging trace.id is to concatenate each request with the relevant data in APM.

OK, I was just curious if you were using it for logging or something else. We have integrations for a few different loggers: Supported Technologies | APM Go Agent Reference [2.x] | Elastic.

[EDDYCJY (JianYu)]

@axw Thank you for your reminder, it’s normal after adjusting the order of the interceptors.