How to get the traceId, parentId, spanId of current request to use outside the tracer?

[shinmyung0]

So I am currently trying to inject the traceId, parentId, spanId into a custom logger. When I try out the ConsoleRecorder I can see that the information is there within the record that is being passed in. But what I want is to not log at the record level, because I want to be able to control what I log.

What would be best is if I could have some handle on what the current traceId is within the context so that I can inject these values into a custom logger so that I can use log correlation later, similar to what the Spring Cloud Sleuth project does to the slf4j logger.

I initially thought that the tracer.id property had these values, but when I compared it with the output from the ConsoleRecorder, I see that the ids are all different.

This some sample console output:

tracer.id.traceId :  785a908c8d93b2d2
tracer.id.parentId :  785a908c8d93b2d2
tracer.id.spanId :  785a908c8d93b2d2
Resolving OAuth2 client_credentials grant...
Record at (spanId=b80c7032456aa95a, parentId=b80c7032456aa95a, traceId=b80c7032456aa95a): ServiceName("bff-service")
Record at (spanId=b80c7032456aa95a, parentId=b80c7032456aa95a, traceId=b80c7032456aa95a): Rpc("POST")
Record at (spanId=b80c7032456aa95a, parentId=b80c7032456aa95a, traceId=b80c7032456aa95a): BinaryAnnotation(http.url="http://10.236.61.221:9095/uaa/oauth/token")
Record at (spanId=b80c7032456aa95a, parentId=b80c7032456aa95a, traceId=b80c7032456aa95a): ClientSend()
Record at (spanId=b80c7032456aa95a, parentId=b80c7032456aa95a, traceId=b80c7032456aa95a): BinaryAnnotation(http.status_code="200")
Record at (spanId=b80c7032456aa95a, parentId=b80c7032456aa95a, traceId=b80c7032456aa95a): ClientRecv()

What am I doing wrong? What is the proper place to grab the right id values?

[codefromthecrypt]

my guess is that when you print the trace ID, one hasn't started yet. There's a Tracer.scope function which allows you to push an ID onto the context (such that downstream reuse it).

[shinmyung0]

Thanks for the quick reply @adriancole. But is there a way I could make sure I grab the trace without manually pushing an ID? The API that I am testing this on is the where the root traceId is generated. I am currently using the zipkin-instrumentation-express library along with zipkin-instrumentation-axios here. I looked at the code for the express middleware, and it seems there is a id being set using Tracer.scoped inside. The last middleware that I have declared is my graphql middleware where my logging is happening. Is there some async thing happening here? I have included more console output to maybe give you guys a better sense of what is happening.

Running GraphQL server on port 4000
registered with eureka:  bff-service/127.0.0.1:bff-service:4000
Record at (spanId=fe1d09be21930dca, parentId=fe1d09be21930dca, traceId=fe1d09be21930dca): ServiceName("bff-service")
Record at (spanId=fe1d09be21930dca, parentId=fe1d09be21930dca, traceId=fe1d09be21930dca): Rpc("POST")
Record at (spanId=fe1d09be21930dca, parentId=fe1d09be21930dca, traceId=fe1d09be21930dca): BinaryAnnotation(http.url="http://localhost:4000/graphql?")
Record at (spanId=fe1d09be21930dca, parentId=fe1d09be21930dca, traceId=fe1d09be21930dca): ServerRecv()
Record at (spanId=fe1d09be21930dca, parentId=fe1d09be21930dca, traceId=fe1d09be21930dca): LocalAddr(host="InetAddress(10.236.61.221)", port=0)
Inside graphql context callback :: traceId:  a62f7dc5b25f8cbf
Resolving query::clientToken
Building url for service :  uaa-service
Returning route : http://10.236.61.221:9095/uaa/oauth/token
Inside the axiosBuilder:: traceId :  a62f7dc5b25f8cbf
Inside the axiosBuilder:: parentId :  a62f7dc5b25f8cbf
Inside the axiosBuilder:: spanId :  a62f7dc5b25f8cbf
Resolving OAuth2 client_credentials grant...
Record at (spanId=b1e0c06bb692707c, parentId=b1e0c06bb692707c, traceId=b1e0c06bb692707c): ServiceName("bff-service")
Record at (spanId=b1e0c06bb692707c, parentId=b1e0c06bb692707c, traceId=b1e0c06bb692707c): Rpc("POST")
Record at (spanId=b1e0c06bb692707c, parentId=b1e0c06bb692707c, traceId=b1e0c06bb692707c): BinaryAnnotation(http.url="http://10.236.61.221:9095/uaa/oauth/token")
Record at (spanId=b1e0c06bb692707c, parentId=b1e0c06bb692707c, traceId=b1e0c06bb692707c): ClientSend()
Record at (spanId=b1e0c06bb692707c, parentId=b1e0c06bb692707c, traceId=b1e0c06bb692707c): BinaryAnnotation(http.status_code="200")
Record at (spanId=b1e0c06bb692707c, parentId=b1e0c06bb692707c, traceId=b1e0c06bb692707c): ClientRecv()
Successfully got client token, returning token object...
POST /graphql? | Authorization: - | 200 54.865
Record at (spanId=fe1d09be21930dca, parentId=fe1d09be21930dca, traceId=fe1d09be21930dca): BinaryAnnotation(http.status_code="200")
Record at (spanId=fe1d09be21930dca, parentId=fe1d09be21930dca, traceId=fe1d09be21930dca): ServerSend()

So the request hits the zipkinExpressMiddleware -> graphql middleware -> outbound request to some user service using axios instrumented with zipkin -> then returns the result of that back to the user.

There is also a callback function inside of my graphql middleware to set the context up, which is where the graphql log statement is from. The graphql middleware is declared after the zipkinExpressMiddleware. I also use Eureka and inside of my graphql resolvers I build a axios instance to so that I can fetch the user-service urls from the Eureka registry and build a url. As you can see from the output I get a completely different traceId from what was already set at the zipkinExpressMiddleware. Is there a different way I should accessing this, not tracer.id? Or is there something tricky going on with async and cls here?

Edit: Also I noticed that the traceId that is being sent out from the zipkin-instrumentation-axios is different from what was also set from the zipkin middleware as well. Could this have something to do with it, or is it just a bug on that library?

[codefromthecrypt]

I don't have much experience in this, suffice to say that things untested aren't going to work well. For example, in the java project brave, we added tests to ensure that the trace scope was readable from other callbacks. When I put these tests in I found most tools didn't work. We then fixed them. Ex here's a test where we read the current trace id on a user filter stuff it into a header (just so that we can later test it) https://github.com/openzipkin/brave/blob/master/instrumentation/http-tests/src/main/java/brave/http/ITServlet25Container.java#L64 https://github.com/openzipkin/brave/blob/master/instrumentation/http-tests/src/main/java/brave/http/ITServlet25Container.java#L79 Is there a way you can help add tests to cover the behavior you are looking for? For advice on CLS I need to defer to folks with javascript experience.

[shinmyung0]

So I've narrowed down the problem to the CLSContext being lost inside of my Apollo graphql server middleware. Can anyone with more familiarity with cls maybe weigh in on this?

*Update: I've found an ugly fix for this. Basically I think the problem is related to how I am initializing my graphql middleware. Basically, the apollo-server-express package provides an async middleware initializer, which is where I lose my active CLSContext. I solved this basically by writing another middleware before the graphql middleware, that grabs the traceId context from the tracer and then sets it onto the req object. Then I reset the id inside of my graphql middleware using the req object. I know this kind of defeats the whole purpose of cls, but not sure what better alternatives are? Code below.

app.use('/graphql', (req, res, next) => {
    req.traceContext = tracer.id;
    next();
});
app.use('/graphql', bodyParser.json(), graphqlExpress((req) => {

    console.log('=> manually setting the tracer context from request object');
    tracer.setId(req.traceContext);

    return {
        schema: schema,
        context: {
            headers: req.headers
        }
    };
}));

I'm not that familiar with how cls and AsyncListeners work, so open to suggestions here from some Node gurus.

[codefromthecrypt]

if you can narrow it to CLS being lost across your middleware, it is possible you could ask apollo for help? Then you could take that recommendation into your middleware and solve the problem.

[shinmyung0]

Thank you for your help. I will take it up on their end.

[vbachev]

I've ran into a similar issue and wanted to share what helped me work around it.

I'm running and express app with both apollo-server-express v2 and zipkin instrumentation with zipkin-context-cls attached as middlewares.

I've noticed that the zipkin trace IDs inside my GraphQL resolvers are not always what I expect them to be 🔥

I then noticed that Apollo uses the body-parser middleware which might trigger this known issue described here: https://github.com/openzipkin/zipkin-js/tree/master/packages/zipkin-context-cls#troubleshooting

I had the zipkin middleware attached BEFORE the apollo server middleware which must have meant that body-parser was being attached after zipkin and was triggering the known issue.

Adding body-parser as an explicit dependency and attaching it as middleware before the zipkin middleware solved the issue for me 👍