Pinpoint doesn't add interceptor for okhttp client

[yonger1516]

The target application has okhttp client(2.4) dependency,pinpoint log it:

2015-11-03 16:37:59 [INFO ](c.n.p.p.p.ProfilerPluginLoader :55) Loading plugin: com.navercorp.pinpoint.plugin.okhttp.OkHttpPlugin 2015-11-03 16:37:59 [DEBUG](c.n.p.p.o.OkHttpPlugin :288) [OkHttp] Initialized config=OkHttpPluginConfig{cookie=true, cookieDumpType=EXCEPTION, cookieSamplingRate=10, entity=false, entityDumpType=EXCEPTION, entitySamplingRate=1, statusCode=true, async=true} 2015-11-03 16:37:59 [DEBUG](c.n.p.p.o.OkHttpPlugin :283) [OkHttp] Add Call class. 2015-11-03 16:37:59 [DEBUG](c.n.p.p.o.OkHttpPlugin :283) [OkHttp] Add Dispatcher class. 2015-11-03 16:37:59 [DEBUG](c.n.p.p.o.OkHttpPlugin :283) [OkHttp] Add AsyncCall class.

...

classloader can detect it : 2015-11-03 16:38:00 [INFO ](c.n.p.p.i.JavassistClassPool :69) lib:file:/usr/local/51test/microService/gateway-server-1.0-SNAPSHOT-31.jar!/lib/converter-jackson-1.9.0.jar!/ 2015-11-03 16:38:00 [INFO ](c.n.p.p.i.JavassistClassPool :69) lib:file:/usr/local/51test/microService/gateway-server-1.0-SNAPSHOT-31.jar!/lib/okhttp-2.4.0.jar!/ 2015-11-03 16:38:00 [INFO ](c.n.p.p.i.JavassistClassPool :69) lib:file:/usr/local/51test/microService/gateway-server-1.0-SNAPSHOT-31.jar!/lib/okio-1.4.0.jar!/ 2015-11-03 16:38:00 [INFO ](c.n.p.p.i.JavassistClassPool :69) lib:file:/usr/local/51test/microService/gateway-server-1.0-SNAPSHOT-31.jar!/lib/slf4j-api-1.7.12.jar!/ 2015-11-03 16:38:00 [DEBUG](c.n.p.p.u.JavaAssistUtils :530) 0 start_pc:0 index:0 name:this nameIndex:414

But I can't find okhttpclient be instrumented in the subsequent log file while set loglevel to debug, also the call sequence graph doesn't display correctly, no next target node point to and no more deep trace in stack trace tree.

I am using master branch and build for '1.5.0-SNAPSHOT'.

[Xylus]

Hi yonger1516, Just got done testing okhttp client (2.4) and it seems alright.

Could you tell us how the application is ran - Is it a Tomcat app? Spring Boot? Or a generic Java app? Traces need an entry point (such as Tomcat receiving a request) to start a Span and without these, subsequent tracing will not be done.

If traces are being created and it's just the okhttp client calls are missing, we might be missing an interception point in the plugin. If this is the case, could you post how you make the HTTP call? And how the Request is built?

[yonger1516]

HiHyunGil, My application run as spring boot and the embedded tomcat used as web server. So the trace can be created, you can get it from this screenshot:

For the RPC communication implementation, we have two solution in two business system, pinpoint missing both of them. System A wrapped ‘com.ning.http.client.AsyncHttpClient’, and set it to the retrofit http client.

System B use spring cloud netflix framework(http://cloud.spring.io/spring-cloud-netflix/spring-cloud-netflix.html), and inject OKHttp client as it http client, business level used it such as :

Thanks Yonger

Original Message Sender:HyunGil Jeongnotifications@github.com Recipient:naver/pinpointpinpoint@noreply.github.com Cc:yonger1516sum2000@live.cn Date:Wednesday, Nov 4, 2015 09:58 Subject:Re: [pinpoint] Pinpoint doesn't add interceptor for okhttp client(#1153)

Hi yonger1516, Just got done testing okhttp client (2.4) and it seems alright. Could you tell us how the application is ran - Is it a Tomcat app? Spring Boot? Or a generic Java app? Traces need an entry point (such as Tomcat receiving a request) to start a Span and without these, subsequent tracing will not be done. If traces are being created and it's just the okhttp client calls are missing, we might be missing an interception point in the plugin. If this is the case, could you post how you make the HTTP call? And how the Request is built? — Reply to this email directly or view it on GitHub.

[yonger1516]

PS,in system A, we use netflix hystrix as high level RPC component(System B also seems too).

Original Message Sender:sum2000sum2000@live.cn Recipient:naver/pinpointpinpoint@noreply.github.com; naver/pinpointreply@reply.github.com Date:Wednesday, Nov 4, 2015 11:47 Subject:Re: [pinpoint] Pinpoint doesn't add interceptor for okhttp client(#1153)

HiHyunGil, My application run as spring boot and the embedded tomcat used as web server. So the trace can be created, you can get it from this screenshot:

For the RPC communication implementation, we have two solution in two business system, pinpoint missing both of them. System A wrapped ‘com.ning.http.client.AsyncHttpClient’, and set it to the retrofit http client.

System B use spring cloud netflix framework(http://cloud.spring.io/spring-cloud-netflix/spring-cloud-netflix.html), and inject OKHttp client as it http client, business level used it such as :

Thanks Yonger

Original Message Sender:HyunGil Jeongnotifications@github.com Recipient:naver/pinpointpinpoint@noreply.github.com Cc:yonger1516sum2000@live.cn Date:Wednesday, Nov 4, 2015 09:58 Subject:Re: [pinpoint] Pinpoint doesn't add interceptor for okhttp client(#1153)

Hi yonger1516, Just got done testing okhttp client (2.4) and it seems alright. Could you tell us how the application is ran - Is it a Tomcat app? Spring Boot? Or a generic Java app? Traces need an entry point (such as Tomcat receiving a request) to start a Span and without these, subsequent tracing will not be done. If traces are being created and it's just the okhttp client calls are missing, we might be missing an interception point in the plugin. If this is the case, could you post how you make the HTTP call? And how the Request is built? — Reply to this email directly or view it on GitHub.

[Xylus]

Had a quick look at Hystrix so this might not be entirely correct.

From what I've gathered, Hystrix seems to wrap RPC calls in a HystrixCommand or HystrixObservableCommand (link). Wrappers by themselves should not affect the actual RPC calls from being traced. What does affect tracing however is the sentences afterwards.

which typically executes within a separate thread

Tracing is made possible by trace context being propagated down the executing thread via thread-local. Synchronous executions therefore do not need to worry about context propagation. For asynchronous executions, this doesn't work. There needs to be mechanism that propagates context to the new thread from the old one.

Pinpoint does this by attaching the context to an object that is passed to the new thread, where it can once again be stored inside a thread-local. This however can only be done on a case-by-case basis (such as com.squareup.okhttp.Call$AsyncCall.execute via the okhttp client plugin).

In order to make this possible, it seems like there needs to be a way to propagate trace context into the new thread that executes Hystrix wrappers.

Again, this might not be the whole reason why the RPC calls are not being traced, but it seems like it definitely is one reason.

[yonger1516]

I nearly agree with you analysis. But is possible to pass the trace context to another thread in another pool? There may be another solution, we can intercept request creator or something else, import trace context info into request before it entering hystrix pool, is this make sense ?

Thank you Yonger

Original Message Sender:HyunGil Jeongnotifications@github.com Recipient:naver/pinpointpinpoint@noreply.github.com Cc:yonger1516sum2000@live.cn Date:Wednesday, Nov 4, 2015 14:42 Subject:Re: [pinpoint] Pinpoint doesn't add interceptor for okhttp client(#1153)

Had a quick look at Hystrix so this might not be entirely correct. From what I've gathered, Hystrix seems to wrap RPC calls in a HystrixCommand or HystrixObservableCommand (link). Wrappers by themselves should not affect the actual RPC calls from being traced. What does affect tracing however is the sentences afterwards. which typically executes within a separate thread Tracing is made possible by trace context being propagated down the executing thread via thread-local. Synchronous executions therefore do not need to worry about context propagation. For asynchronous executions, this doesn't work. There needs to be mechanism that propagates context to the new thread from the old one. Pinpoint does this by attaching the context to an object that is passed to the new thread, where it can once again be stored inside a thread-local. This however can only be done on a case-by-case basis (such as com.squareup.okhttp.Call$AsyncCall.execute via the okhttp client plugin). In order to make this possible, it seems like there needs to be a way to propagate trace context into the new thread that executes Hystrix wrappers. Again, this might not be the whole reason why the RPC calls are not being traced, but it seems like it definitely is one reason. — Reply to this email directly or view it on GitHub.

[Xylus]

Yes, it is possible. Your second suggestion sounds promising. There just needs a way for the thread inside the Hystrix pool to intercept the request object, get the context and bind it to thread-local.

Seems like a great case for a Hystrix plugin :)

[yonger1516]

Are you ready or plan to implement it?

Original Message Sender:HyunGil Jeongnotifications@github.com Recipient:naver/pinpointpinpoint@noreply.github.com Cc:yonger1516sum2000@live.cn Date:Wednesday, Nov 4, 2015 18:44 Subject:Re: [pinpoint] Pinpoint doesn't add interceptor for okhttp client(#1153)

Yes, it is possible. Your second suggestion sounds promising. There just needs a way for the thread inside the Hystrix pool to intercept the request object, get the context and bind it to thread-local. Seems like a great case for a Hystrix plugin :) — Reply to this email directly or view it on GitHub.

[Xylus]

No immediate plans yet as we're focusing on getting 1.5.0 out the door. If you'd like to take a crack at it, we've got a plugin-sample that will guide you through the development process.

[yonger1516]

OK, I am reading the plugin-sample source code, I will try to custom the plugin for my requirement. And I also really expect your 1.5.0 release, the end-to-end feature is the one which I want to use ASAP. Is there any detail plan to these features?

Original Message Sender:HyunGil Jeongnotifications@github.com Recipient:naver/pinpointpinpoint@noreply.github.com Cc:yonger1516sum2000@live.cn Date:Thursday, Nov 5, 2015 10:25 Subject:Re: [pinpoint] Pinpoint doesn't add interceptor for okhttp client(#1153)

No immediate plans yet as we're focusing on getting 1.5.0 out the door. If you'd like to take a crack at it, we've got a plugin-sample that will guide you through the development process. — Reply to this email directly or view it on GitHub.

[Xylus]

Awesome, let us know if you've got any questions regarding plugin development.

End-to-end feature has been in the talks for a while now but it won't be part of 1.5.0 release unfortunately. We'll look into starting it soon though so do keep an eye out.

[yonger1516]

What a pity. Is there any email or IM commication approach of you? Then I can send you the questions in developing, and also get the response faster.

Original Message Sender:HyunGil Jeongnotifications@github.com Recipient:naver/pinpointpinpoint@noreply.github.com Cc:yonger1516sum2000@live.cn Date:Thursday, Nov 5, 2015 15:26 Subject:Re: [pinpoint] Pinpoint doesn't add interceptor for okhttp client(#1153)

Awesome, let us know if you've got any questions regarding plugin development. End-to-end feature has been in the talks for a while now but it won't be part of 1.5.0 release unfortunately. We'll look into starting it soon though so do keep an eye out. — Reply to this email directly or view it on GitHub.

[Xylus]

There's a gitter channel for plugin development, which should be the fastest way to get a response.

[Xylus]

Closing this for now as it seems to be issue with trace not propagating to other threads managed by Hystrix. Will have to look into Hystrix to figure out a way to propagate context.