-
Notifications
You must be signed in to change notification settings - Fork 59
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Initial implementation #1
Initial implementation #1
Conversation
d46d7ec
to
3a98697
Compare
@mabn repository has been moved here. Thanks for your previous review. If you would like to look at this again it would be great 👍 . |
@Override | ||
public void onAfterCompletion(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, | ||
Object handler, Exception ex, Span span) { | ||
Tags.HTTP_STATUS.set(span, httpServletResponse.getStatus()); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'd also add an error tag (see https://github.com/opentracing/specification/blob/master/data_conventions.yaml#L16)
I'm not sure when exactly though. Probably testing for ex != null
and ignoring http status code would be fine.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why would you ignore http.status_code
tag? IIRC server can respond with different status codes for different exceptions.
I was also thinking about error
tag when exception was added to onAfterCompletion
. Finally it's there 👍
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I meant not to base the decision about adding an error tag on the status code but only on the presence of the exception. This way you avoid having to decide if 404 is an error or just a nice REST response for "record not found"
Looks nice, I especially like those decorators. One thing I'm concerned about are requests which won't hit the interceptor. I believe that for example spring security filter chain is executed before interceptors. Same thing would be true for request which do not match any request mapping or cause exceptions in some server filter. Ideally I'd like a servlet filter that can be registered as the first one in the filter chain which would cooperate with the interceptor - servlet filter would open a span and fill some basic information (http method, uri, exception if thrown) and the interceptor could enrich it with additional details - like the exception thrown from the controller or the details of the handler that handled the request. |
7f52b7e
to
34e3f95
Compare
@mabn Thanks for the review! It is very helpful 👍 Issues highlighted in your comment:
This currently depends on https://github.com/opentracing-contrib/java-spring-web, |
} | ||
spanWrapper = new SpanWrapper(serverSpan, true); | ||
httpServletRequest.setAttribute(ACTIVE_SPAN, spanWrapper); | ||
}else if (spanWrapper == null && httpServletRequest.getAttribute(ACTIVE_SPAN) == null && |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
spanWrapper == null && httpServletRequest.getAttribute(ACTIVE_SPAN) == null
I guess one of above is sufficient as spanWrapper == httpServletRequest.getAttribute(ACTIVE_SPAN)
5c95cd9
to
872b4ed
Compare
@GBrown @jpkrohling could you please review? review notes: |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I can't judge the Spring semantics, but it looks OK to me. I added a few comments, but nothing really that serious.
if (httpServletRequest.getAttribute(WebUtils.ERROR_REQUEST_URI_ATTRIBUTE) != null) { | ||
try { | ||
URL url = new URL(httpServletRequest.getRequestURL().toString()); | ||
url.getProtocol(); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This code is lost here :)
try { | ||
URL url = new URL(httpServletRequest.getRequestURL().toString()); | ||
url.getProtocol(); | ||
String errorUrl = url.getProtocol() + "://" + url.getHost() + ":" + url.getPort() + |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Would be more readable with String.format("%s://%s:%s%s", protocol, host, port, errorRequestUriAttribute)
Tags.HTTP_URL.set(span, errorUrl); | ||
} catch (MalformedURLException e) { | ||
log.severe("failed to construct error URL"); | ||
e.printStackTrace(); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Instead of printing the stack trace, see if you can pass the exception to the log.severe/log.error . This way, the system administrator can shut it up in case it's too noisy. If you do a e.printStackTrace
, there's no way to disable just this one.
} | ||
|
||
private Map<String, String> logsForException(Throwable throwable) { | ||
Map<String, String> errorLog = new HashMap<>(); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
You know for sure you will have only 3 entries on the map. Use the constructor to tell it to allocate only 3 positions, instead of the 16 that it does by default.
throwable.getMessage(); | ||
errorLog.put("message", exMessage); | ||
|
||
StringWriter sw = new StringWriter(); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
So, you are adding event
, message
and stack trace
to the span. Probably not something for now, but you might want to add a todo item to allow customization of this. I can think of several reasons not to log the entire stack trace to a span :)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Users can implement their own span decorator. I understand your point.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Personally, I would do this differently. I would log the following fields only:
- event: "exception"
- exception: throwable
and let the tracer implementation deal with exact representation of the exception / stack trace.
return new ExceptionFilter(); | ||
} | ||
|
||
// @Bean |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Left over?
public FilterRegistrationBean tracingFilterRegistration() { | ||
FilterRegistrationBean registrationBean = new FilterRegistrationBean(); | ||
TracingFilter tracingFilter = new TracingFilter(mockTracer, Arrays.asList( | ||
io.opentracing.contrib.web.servlet.filter.SpanDecorator.STANDARD_TAGS), |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
static import
those constants?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This is a left over when I was testing integration with servlet filter. The whole block is removed.
HttpEntity<String> entity = new HttpEntity<>(headers); | ||
|
||
restTemplate.exchange("/sync", HttpMethod.GET, entity, String.class); | ||
Awaitility.await().until(reportedSpansSize(), IsEqual.equalTo(1)); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Interesting, I did something similar for APM, as I didn't find any libs that would do this. Remind me to replace our custom made "Wait#until()" by this :)
|
||
@Test | ||
public void testAsync() throws Exception { | ||
{ |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why this anonymous block inside the method?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Actually I like this I can clearly see that nothing from inside a block is propagated to asserts.
|
||
@Test | ||
public void testAsyncDeferred() throws Exception { | ||
{ |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Ditto
4efc953
to
af691d0
Compare
af691d0
to
a847863
Compare
@bensigelman @yurishkuro could you please review? |
URL url = new URL(httpServletRequest.getRequestURL().toString()); | ||
String errorUrl = String.format("%s://%s:%s%s", url.getProtocol(), url.getHost(), url.getPort(), | ||
httpServletRequest.getAttribute(WebUtils.ERROR_REQUEST_URI_ATTRIBUTE)); | ||
Tags.HTTP_URL.set(span, errorUrl); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I am not familiar with this part of the framework - why do you need to override the URL tag if it was already set in onPreHandle
? Perhaps add a comment to this section.
throwable.getMessage(); | ||
errorLog.put("message", exMessage); | ||
|
||
StringWriter sw = new StringWriter(); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Personally, I would do this differently. I would log the following fields only:
- event: "exception"
- exception: throwable
and let the tracer implementation deal with exact representation of the exception / stack trace.
/** | ||
* Tracing handler interceptor for spring web. It creates a new span for an incoming request. | ||
* Created span can be accessed via {@link HttpServletRequest#getAttribute(String)} with name | ||
* {@link TracingHandlerInterceptor#ACTIVE_SPAN}. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This seems like it would severely reduce the usefulness of the instrumentation, since the span is not propagated to any outbound calls this service might make. Basically, the instrumentation like this is most useful when there's an established standard for in-process context/span propagation.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
If you want to make outbound calls you need to active span from attributes and pass it to instrumented client lib, which is not very handy at the moment.
As it was mentioned on gitter channel I hope that there will be some API changes to access active span context.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Personally, I would do this differently. I would log the following fields only:
event: "exception"
exception: throwable
and let the tracer implementation deal with exact representation of the exception / stack trace.
I agree this depends on tracer impl, probably users using some specific tracer would use different decorator. As this is a "standard" decorator, I wanted to add the most common tag/event to represent an error in the system.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This is based on opentracing/specification#29 (comment)
a847863
to
afd8b38
Compare
9a77f14
to
7ba0a50
Compare
7c4cf68
to
eb55100
Compare
Update: I have added the same tests for Spring MVC deployed on jetty and in following scenarios interceptor is not invoked:
In spring boot tracing interceptor is invoked in all of these use cases. I will do a bit more research and if not I will document it and refer to java-web-filter. |
eb55100
to
41799be
Compare
You can use
|
4f86d16
to
3f858f4
Compare
@mabn thanks, I know when an error is being handled. I'm still not very happy with this... I will force consumers of this instrumentation to use web filter and this tracing interceptor together. That is the only way how to trace all requests for spring MVC (and boot). Span will be started in filter and interceptor will decorate span with spring objects (handler..). |
@pavolloffay I have been reading the javadocs for the Spring stuff. How infuriating that the One idea would be to use This would capture state about what's going on. Whether the tracing system will display it sanely is another matter. But in some way I think I prefer this to hacks that rely on the web filter, etc. My two cents. A bit of a predicament :-/ (A nuclear option would be a PR against Spring itself, as this seems busted to me... but that's a long-term fix that doesn't address the software being used in the wild.) |
I wouldn't consider it a hack (the code I pasted is a hack though). Spring MVC is based on servlets and lives inside a DispatcherServlet. Spring Security adds a filter various authentication mechanisms. The most reasonable way to cover all these behaviours is to add tracing servlet filter early in the filter chain and then customize current span (alter operation_name, add tags...) inside other filters / interceptors. Tracing error controlled execution as FollowsFrom would be kind of weird because the parent span (http request) has to wait for error controller execution anyway. |
(btw. spring cloud sleuth uses servlet filter with interceptor, I think it is the only way how to properly get trace data for all use cases [no URL mapping, unauthenticated requests..], see https://jira.spring.io/browse/SPR-15226) The thing is
and I think this can happen often. My issue with an exception in a cotroller (deployed in embedded boot) is that request is just forwarded e.g. I think we should add a log or create new span in every invocation of When used filter+interceptor:
HTTP tags and errors are added in filter. XX results in one span per request. In a handler you can create a local span representing operation in a given handler, but to find out in which handler it was created you need to look at logs. If we go with YY then there would be one root span for a request and N children for each handler invocation and if you create a span in a handler you know more explicitly in which handler it happened. YY gives you a cleaner span structure but is more verbose. When used without filter:
HTTP tags would be added in interceptor decorator. Decorator would also know #number of created spans before (to do not add the same tags again). (*)Spring MVC execute sequence for async:
in spring boot it's just Based on all this I think we should go with filter+interceptor together and then decide if a child span should be created or not. |
Flow for Spring boot deployed in embedded container when an exception is thrown in a controller:
Based on this sometimes I would have to start span in interceptor and have a way to check if parent span from filter is finished or not... 😟 |
@pavolloffay I do not know enough about Spring to provide very useful feedback here. If it would be useful to get on a google hangout or similar to brainstorm possible workarounds, I'm happy to do so, for what it's worth. |
@bensigelman @mabn I have updated the PR description. See how does it work. The goal is that it maximizes the use of span created in filter and creates additional span only if necessary (e.g. when span from filter is finished). |
d93e29e
to
91bbe81
Compare
README.md
Outdated
* exceptions in filters | ||
|
||
, however these requests are not traced in Spring MVC application deployed in tomcat/jetty... | ||
To solve this problem consider using [web filter instrumentation](https://github.com/pavolloffay/java-spring-web). |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
URL is wrong. Should be https://github.com/opentracing-contrib/java-web-servlet-filter
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thanks, the whole Readme has to be updated.
Object handler, Exception ex, Span span) { | ||
Map<String, Object> logs = new HashMap<>(2); | ||
logs.put("event", "afterCompletion"); | ||
logs.put("handler", handler); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Shouldn't this be same as onPreHandler
- use MetaDataUtils.HANDLER
, but also log the class and method names separately?
|
||
span = mockSpans.get(1); | ||
Assert.assertEquals(0, span.tags().size()); | ||
assertLogEvents(span.logEntries(), Arrays.asList("preHandle", "afterCompletion")); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
May be worth checking that this span is a child of the server span?
} | ||
} | ||
|
||
public static void assertErrors(List<MockSpan> spans) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Would be better named assertNoErrors
/** | ||
* @author Pavol Loffay | ||
*/ | ||
public class TextMapPropagator implements MockTracer.Propagator { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Is this here while waiting for release of opentracing-java? If so, 0.20.8 is now available
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LGTM, although I can't judge the Spring parts.
*/ | ||
class InterceptorSpanWrapper extends SpanWrapper { | ||
|
||
private Object handler; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
What is this handler? Can't you add a parameter to this class, so that you have a real type, instead of using Object
?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It is a handler object passed to the spring interceptor, they use object too.
import io.opentracing.contrib.web.servlet.filter.SpanWrapper; | ||
|
||
/** | ||
* @author Pavol Loffay |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Would be nice to have a line or two that explains that this class is about.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
+1 Will write something, however it is an internal class.
} | ||
|
||
for (SpanDecorator decorator: decorators) { | ||
decorator.onPreHandle(httpServletRequest, handler, serverSpan); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
What happens if a decorator fails? Will it propagate to the request? Should it?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Good comment, I'm assuming that decorators won't throw any exceptions.
} | ||
|
||
for (SpanDecorator decorator: decorators) { | ||
decorator.onAfterCompletion(httpServletRequest, httpServletResponse, handler, ex, serverSpan); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Same here: what happens if a decorator throws an exception? Should it propagate to the end user?
* @author Pavol Loffay | ||
*/ | ||
@SpringBootTest( | ||
webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT, |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
\o/
public Callable<String> async() { | ||
return new Callable<String>() { | ||
public String call() throws Exception { | ||
Thread.sleep(1000); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
We talked about a similar code in a previous PR, and I have similar concerns here :)
private List<SpanDecorator> spanDecorators; | ||
|
||
@Autowired | ||
private io.opentracing.Tracer tracer; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why are you using the fully qualified class name here?
@@ -0,0 +1,3 @@ | |||
<!DOCTYPE html> | |||
<body/> |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
What is this file for? Is this something that Spring requires?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It is used to test ControllerView
and returning view.
pom.xml
Outdated
|
||
<version.com.jayway.awaitility-awaitility>1.7.0</version.com.jayway.awaitility-awaitility> | ||
<version.io.opentracing>0.20.9</version.io.opentracing> | ||
<version.io.opentracing.contrib-opentracing-web-servlet-filter>0.0.3-SNAPSHOT</version.io.opentracing.contrib-opentracing-web-servlet-filter> |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Just to confirm: you'll change this before merging, right?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yep, the filter needs to be released. (CI is failing)
5bc0232
to
4a3565e
Compare
@pavolloffay basic question: I would have casually expected that exceptions thrown during servlet/interceptor invocation would lead to |
These errors are propagated to the web filter. Web filter is basically adding all tags (HTTP, error). You can see it in tests that error tag/logs are present. |
Assert.assertEquals(getUrl("/exception"), span.tags().get(Tags.HTTP_URL.getKey())); | ||
Assert.assertEquals(500, span.tags().get(Tags.HTTP_STATUS.getKey())); | ||
Assert.assertNotNull(span.tags().get(Tags.COMPONENT.getKey())); | ||
Assert.assertEquals(Boolean.TRUE, span.tags().get(Tags.ERROR.getKey())); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yes, I see this now. Thanks @pavolloffay. (I was previously looking for non-test code that sets the error tag)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'm really just reviewing the basic API... I am a little sad about the followsFrom thing, but I also have no counterproposal. It may be worth filing an issue with Spring Web just to let them know that their programming model makes things like this awkward.
I am not going to do any fine-grained commenting as many others are doing that better than I would anyway :)
Thank you so much for sorting through this, @pavolloffay!
@mabn @jpkrohling @objectiser @yurishkuro @bensigelman thanks for review/s 👍 ! |
31a7e71
to
56eaa22
Compare
Issue created: https://jira.spring.io/browse/SPR-15265 |
Import from old repository with an initial implementation.
How does this work?
afterCompletion
for the same handler which was passed topreHandle
. Context of this span overrides context of span created in servlet filter (so created spans in error controllers will be children of it).Test coverage:
These tests are run for embedded boot deployed on tomcat and also for MVC deployed on jetty.
This depends on: