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

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.

@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?

@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.

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

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: https://www.elastic.co/guide/en/apm/agent/go/current/supported-tech.html#supported-tech-logging.

1 Like

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

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.