Skip to content

issue-557 added automatically span creation for DispatcherTypes: FORWARD, INCLUDE, ERROR#1212

Merged
SylvainJuge merged 10 commits intoelastic:masterfrom
videnkz:issue-557-track-spans-request-dispatcher-forward-include
Aug 21, 2020
Merged

issue-557 added automatically span creation for DispatcherTypes: FORWARD, INCLUDE, ERROR#1212
SylvainJuge merged 10 commits intoelastic:masterfrom
videnkz:issue-557-track-spans-request-dispatcher-forward-include

Conversation

@videnkz
Copy link
Contributor

@videnkz videnkz commented Jun 1, 2020

closes #557
reopened from #557

closes #384

  • changelog
  • test
  • integration-test
  • capture exception from headers
  • fixed logic with early span creation
  • added to documentation (supported technologies page)
@videnkz videnkz force-pushed the issue-557-track-spans-request-dispatcher-forward-include branch from 9dfa4cc to e33b14d Compare June 1, 2020 20:01
@ghost
Copy link

ghost commented Jun 1, 2020

💚 Build Succeeded

Pipeline View Test View Changes Artifacts preview

Expand to view the summary

Build stats

  • Build Cause: [Pull request #1212 updated]

  • Start Time: 2020-08-21T14:32:27.600+0000

  • Duration: 46 min 52 sec

Test stats 🧪

Test Results
Failed 0
Passed 1464
Skipped 11
Total 1475

@videnkz
Copy link
Contributor Author

videnkz commented Jun 2, 2020

ebsphere] 2020-06-02 05:53:49,984 [elastic-apm-circuit-breaker] INFO  co.elastic.apm.agent.impl.circuitbreaker.CircuitBreaker - Stopping the Circuit Breaker thread.
[websphere] 2020-06-02 05:53:49,984 [Framework stop] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation ExecutorRunnableInstrumentation: ((((hasSuperType(erasure(name(equals(java.util.concurrent.Executor)))) and not(name(equals(org.apache.felix.resolver.ResolverImpl$DumbExecutor)))) and not(name(startsWith(com.hazelcast)))) and not((name(contains($Proxy)) or name(contains($$))))) and not(isInterface())) matches class java.util.concurrent.ForkJoinPool
[websphere] 2020-06-02 05:53:49,985 [Framework stop] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation ExecutorCallableInstrumentation: ((((hasSuperType(erasure(name(equals(java.util.concurrent.Executor)))) and not(name(equals(org.apache.felix.resolver.ResolverImpl$DumbExecutor)))) and not(name(startsWith(com.hazelcast)))) and not((name(contains($Proxy)) or name(contains($$))))) and not(isInterface())) matches class java.util.concurrent.ForkJoinPool
[websphere] [AUDIT   ] CWWKT0017I: Web application removed (default_host): https://08df9efac3d5:9443/simple-webapp/
[websphere] [AUDIT   ] CWWKT0017I: Web application removed (default_host): https://08df9efac3d5:9443/cdi-app/
[websphere] [AUDIT   ] CWWKT0017I: Web application removed (default_host): https://08df9efac3d5:9443/jsf-http-get/
[websphere] 2020-06-02 05:53:50,033 [Framework stop] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation ExecutorRunnableInstrumentation: ((((name(equals(execute)) and returns(erasure(is(void)))) and hasParameter(hasTypes(erasures(containing(is(interface java.lang.Runnable)))))) or ((name(equals(submit)) and returns(erasure(is(interface java.util.concurrent.Future)))) and hasParameter(hasTypes(erasures(containing(is(interface java.lang.Runnable))))))) or ((name(equals(submit)) and returns(erasure(is(interface java.util.concurrent.Future)))) and hasParameter(hasTypes(erasures(containing(is(interface java.lang.Runnable), is(class java.lang.Object))))))) matches public void java.util.concurrent.ForkJoinPool.execute(java.lang.Runnable)
[websphere] [AUDIT   ] CWWKZ0009I: The application simple-webapp has stopped successfully.
[websphere] [AUDIT   ] CWWKZ0009I: The application cdi-app has stopped successfully.
[websphere] [AUDIT   ] CWWKZ0009I: The application jsf-http-get has stopped successfully.
[websphere] [AUDIT   ] CWWKE0036I: The server defaultServer stopped after 15.941 seconds.
Tests run: 2, Failures: 2, Errors: 0, Skipped: 0, Time elapsed: 53.62 sec <<< FAILURE! - in co.elastic.apm.servlet.WebSphereIT
testAllScenarios[WebSphere 8.5.5](co.elastic.apm.servlet.WebSphereIT)  Time elapsed: 15.743 sec  <<< FAILURE!
org.opentest4j.AssertionFailedError: 

Expecting:
 <5>
to be equal to:
 <2>
but was not.

testAllScenarios[WebSphere webProfile7](co.elastic.apm.servlet.WebSphereIT)  Time elapsed: 9.87 sec  <<< FAILURE!
org.opentest4j.AssertionFailedError: 

Expecting:
 <3>
to be equal to:
 <2>
but was not.


Results :

Failed tests: 
  JBossIT>AbstractServletContainerIntegrationTest.testAllScenarios:264 
Expecting:
 <3>
to be equal to:
 <2>
but was not.
  TomcatIT>AbstractServletContainerIntegrationTest.testAllScenarios:264 
Expecting:
 <4>
to be equal to:
 <2>
but was not.
  TomcatIT>AbstractServletContainerIntegrationTest.testAllScenarios:264 
Expecting:
 <4>
to be equal to:
 <2>
but was not.
  TomcatIT>AbstractServletContainerIntegrationTest.testAllScenarios:264 
Expecting:
 <4>
to be equal to:
 <2>
but was not.
  TomcatIT>AbstractServletContainerIntegrationTest.testAllScenarios:264 
Expecting:
 <4>
to be equal to:
 <2>
but was not.
  TomcatIT>AbstractServletContainerIntegrationTest.testAllScenarios:264 
Expecting:
 <4>
to be equal to:
 <2>
but was not.
  TomcatIT>AbstractServletContainerIntegrationTest.testAllScenarios:264 
Expecting:
 <4>
to be equal to:
 <2>
but was not.
  WebSphereIT>AbstractServletContainerIntegrationTest.testAllScenarios:264 
Expecting:
 <5>
to be equal to:
 <2>
but was not.
  WebSphereIT>AbstractServletContainerIntegrationTest.testAllScenarios:264 
Expecting:
 <3>
to be equal to:
 <2>
but was not.

Tests run: 28, Failures: 9, Errors: 0, Skipped: 1
@videnkz
Copy link
Contributor Author

videnkz commented Jun 2, 2020

with last fix, now I have problem with ServletApiTestApp#testTransactionReportingWithErrorHandling
It fails only on WebsphereIT(webProfile7).
Transaction by some reason not created.

@videnkz
Copy link
Contributor Author

videnkz commented Jun 2, 2020

@felixbarny, I noticed that for some Jetty application container span of DispatcherType.ERROR created, but for example websphere, widlfy, tomcat - not.

@videnkz videnkz force-pushed the issue-557-track-spans-request-dispatcher-forward-include branch 2 times, most recently from 722d42a to 99a0789 Compare June 2, 2020 11:36
@videnkz
Copy link
Contributor Author

videnkz commented Jun 3, 2020

when we call "/simple-webapp" + "/unknown" inServletApiTestApp#testTransactionReportingWithErrorHandling
JettyIT(9.3) fails with error:

ailed tests: 
  JettyIT>AbstractServletContainerIntegrationTest.testAllScenarios:264->AbstractServletContainerIntegrationTest.assertTransactionReported:273->AbstractServletContainerIntegrationTest.getAllReported:338->AbstractServletContainerIntegrationTest.getReportedTransactions:414->AbstractServletContainerIntegrationTest.getEvents:452->AbstractServletContainerIntegrationTest.validateEventMetadata:475->AbstractServletContainerIntegrationTest.validateServiceName:492 [Event has non-expected service name {"timestamp":1591161440603002,"name":"DefaultServlet#doGet","id":"7c4a6aab6a74eda3","trace_id":"191fdaf7ed5f2d2d6876d647b6402b22","type":"request","duration":18.712,"result":"HTTP 4xx","context":{"service":{"name":"Simple Web App"},"request":{"method":"GET","headers":{"Connection":"keep-alive","User-Agent":"okhttp/3.9.1","Host":"localhost:33485","Accept-Encoding":"gzip"},"url":{"full":"http://localhost:33485/simple-webapp/unknown","hostname":"localhost","port":"33485","pathname":"/simple-webapp/unknown","protocol":"http"},"socket":{"encrypted":false,"remote_address":"172.30.0.1"},"http_version":"1.1"},"response":{"finished":true,"headers_sent":true,"status_code":404},"tags":{}},"span_count":{"dropped":0,"started":1},"sampled":true}] 
Expecting:
 <"Simple Web App">
to be equal to:
 <"jsf-http-get">
but was not.
  JettyIT>AbstractServletContainerIntegrationTest.testAllScenarios:264->AbstractServletContainerIntegrationTest.assertTransactionReported:273->AbstractServletContainerIntegrationTest.getAllReported:338->AbstractServletContainerIntegrationTest.getReportedTransactions:414->AbstractServletContainerIntegrationTest.getEvents:452->AbstractServletContainerIntegrationTest.validateEventMetadata:475->AbstractServletContainerIntegrationTest.validateServiceName:492 [Event has non-expected service name {"timestamp":1591161454235002,"name":"DefaultServlet#doGet","id":"a3575d7702a7837d","trace_id":"965887bd126bd2e4e429bf74db52d090","type":"request","duration":16.391,"result":"HTTP 4xx","context":{"service":{"name":"Simple Web App"},"request":{"method":"GET","headers":{"Connection":"keep-alive","User-Agent":"okhttp/3.9.1","Host":"localhost:33486","Accept-Encoding":"gzip"},"url":{"full":"http://localhost:33486/simple-webapp/unknown","hostname":"localhost","port":"33486","pathname":"/simple-webapp/unknown","protocol":"http"},"socket":{"encrypted":false,"remote_address":"172.30.0.1"},"http_version":"1.1"},"response":{"finished":true,"headers_sent":true,"status_code":404},"tags":{}},"span_count":{"dropped":0,"started":1},"sampled":true}] 
Expecting:
 <"Simple Web App">
to be equal to:
 <"jsf-http-get">
but was not.

@videnkz videnkz force-pushed the issue-557-track-spans-request-dispatcher-forward-include branch 2 times, most recently from 6eef95e to db73c87 Compare June 9, 2020 18:53
@felixbarny
Copy link
Member

Sometimes spans from one test can leak to another test. Not sure what the best solution for that is. Maybe to make sure to wait until all expected spans have arrived in each test so that they can't leak into others.

@videnkz videnkz force-pushed the issue-557-track-spans-request-dispatcher-forward-include branch from 0894c24 to ede2933 Compare June 14, 2020 20:37
Copy link
Contributor

@eyalkoren eyalkoren left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Awesome job!
Please see the few comments.
Thanks!

String spanAction = null, spanName = null;
if (dispatcherType == DispatcherType.FORWARD) {
String pathInfo = request.getPathInfo();
spanName = FORWARD + SPACE + request.getServletPath() + (pathInfo != null ? pathInfo : EMPTY);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is allocating four String objects every time. Please use the AbstractSpan#appendToName() API instead (create it before).
Same for the other ones.

Copy link
Contributor Author

@videnkz videnkz Aug 5, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

repalced with appendToName

servletTransactionHelper.fillRequestContext(transaction, request.getProtocol(), request.getMethod(), request.isSecure(),
request.getScheme(), request.getServerName(), request.getServerPort(), request.getRequestURI(), request.getQueryString(),
request.getRemoteAddr(), request.getHeader("Content-Type"));
} else if (transaction == null && servletRequest instanceof HttpServletRequest) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This else statement looks misplaced. Its content should go inside the if above and you can do else with the servletRequest.getDispatcherType() == DispatcherType.REQUEST check.

spanAction = INCLUDE_SPAN_ACTION;
isAllowedType = true;
} else if (dispatcherType == DispatcherType.ERROR) {
spanName = ERROR + SPACE + request.getAttribute(RequestDispatcher.FORWARD_SERVLET_PATH);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why using RequestDispatcher.FORWARD_SERVLET_PATH in this case? I think we want the error page path. The transaction will contain the original servlet path.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

changed to getting

Object servletPath = request.getServletPath();
} else if (dispatcherType == DispatcherType.ERROR) {
spanName = ERROR + SPACE + request.getAttribute(RequestDispatcher.FORWARD_SERVLET_PATH);
spanAction = ERROR_SPAN_ACTION;
isAllowedType = true;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please check if you already get the Exception object stored in the RequestDispatcher.ERROR_EXCEPTION attribute somewhere else. If not, let's create and send an error here with captureException through the parent span.

Comment on lines 94 to 102
for (JsonNode span : test.getReportedSpans()) {
String spanType = span.get("type").textValue();
if ("servlet.request-dispatcher.forward".equals(spanType)) {
isExistForwardSpan = true;
assertThat(span.get("name").textValue()).isEqualTo("FORWARD /servlet");
} else if ("db.h2.query".equals(spanType)) {
isExistDbH2QuerySpan = true;
}
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You need to assert that exactly the expected spans are captured. Potentially, this can pass if two non-related spans are captured.
You can filter the span collection for each and assert you get exactly one that contains the required info.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

added filter before assert.

Copy link
Contributor

@eyalkoren eyalkoren left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for working on that.
I suggest you first merge with master. You will see quite a few changes in the related code.
Then, see if you can apply the requested changes.
Let us know if you need assistance with that.

servletTransactionHelper.fillRequestContext(transaction, request.getProtocol(), request.getMethod(), request.isSecure(),
request.getScheme(), request.getServerName(), request.getServerPort(), request.getRequestURI(), request.getQueryString(),
request.getRemoteAddr(), request.getHeader("Content-Type"));
} else if (transaction == null) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why is the transaction == null required here? Seems it will always be null

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i changed here condition to ->

servletRequest.getDispatcherType() != DispatcherType.ASYNC
Comment on lines 172 to 143
boolean isSpannableDispatcherType = false;
span = parent.createSpan()
.withType(SPAN_TYPE)
.withSubtype(SPAN_SUBTYPE);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do not create a span unless you know we need one. Currently these spans can leak. You must always end a span you created, like you must always deactivate a span you activated (which you did).
In rare cases (this is not one), you may create a span and then requestDiscarding it, but you still must end it.

span.withAction(ERROR_SPAN_ACTION);
isSpannableDispatcherType = true;
}
if (isSpannableDispatcherType && !parent.getNameAsString().equals(span.getNameAsString())) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

getNameAsString is allocating a String objects (so two in this comparison).
There are better ways to avoid creation of same nested spans. For example, before creating a span, see if the parent span has the same type, subtype and action.
What cases are you trying to prevent with this comparison?

kananindzya added 2 commits August 5, 2020 22:21
…ARD, INCLUDE, ERROR

minor fixes with creating span that has same names
added path info for span name of FORWARD, INCLUDE dispatcher types.
delete testTransactionReportingWithErrorHandling test
Update apm-agent-plugins/apm-servlet-plugin/src/main/java/co/elastic/apm/agent/servlet/ServletApiAdvice.java
Co-authored-by: eyalkoren <41850454+eyalkoren@users.noreply.github.com>
Update apm-agent-plugins/apm-servlet-plugin/src/main/java/co/elastic/apm/agent/servlet/ServletApiAdvice.java
Co-authored-by: eyalkoren <41850454+eyalkoren@users.noreply.github.com>
@videnkz videnkz force-pushed the issue-557-track-spans-request-dispatcher-forward-include branch from b5267a3 to e77603e Compare August 5, 2020 17:52
@eyalkoren
Copy link
Contributor

@kananindzya thanks for taking this back. What's the state of this PR? Is it ready for another review?

@videnkz
Copy link
Contributor Author

videnkz commented Aug 6, 2020

@kananindzya thanks for taking this back. What's the state of this PR? Is it ready for another review?

I updated yesterday as per the new changes. But there was a problem with integration tests, the isntrumentation for some reason not working. Today I will try to find the reason.
Next, I should add exception capture from http headers.
And change logic with comparing parent span type, subtype, action, instead of comparing nameAsString.

Copy link
Contributor

@eyalkoren eyalkoren left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @kananindzya, looking good!

I started commenting but decided it's easier to code instead 🙂 .
Please see my suggested changes and if you feel it doesn't contradict anything you intended to do, please merge.
I mainly moved a couple of things around, saving some allocations.

I also removed a crash report you accidentally pushed but I wonder - does this need to trouble us? Do you know what caused this crash?

@videnkz
Copy link
Contributor Author

videnkz commented Aug 11, 2020

Thanks @kananindzya, looking good!

I started commenting but decided it's easier to code instead slightly_smiling_face .
Please see my suggested changes and if you feel it doesn't contradict anything you intended to do, please merge.
I mainly moved a couple of things around, saving some allocations.

I also removed a crash report you accidentally pushed but I wonder - does this need to trouble us? Do you know what caused this crash?

Great! Thanks you. I added exception handling.

@videnkz videnkz requested a review from eyalkoren August 11, 2020 19:32
@videnkz
Copy link
Contributor Author

videnkz commented Aug 11, 2020

I also removed a crash report you accidentally pushed but I wonder - does this need to trouble us? Do you know what caused this crash?

No it shouldn't trouble you. Next time I will be more attentive before pushing changes.

Copy link
Contributor

@eyalkoren eyalkoren left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looking at your addition, I decided to cancel this error reporting. Assuming that the parent of such spans is the transaction, we will get the error reported by the transaction anyway.
I also added a test to demonstrate that.

Comment on lines 259 to 262
} else {
if (Boolean.TRUE.equals(isExceptionAttributeCaptured.get())) {
t2 = null;
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, we can't do that as we don't know if it's the same exception or not.

Copy link
Contributor

@eyalkoren eyalkoren left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Awesome!! 🎉

@eyalkoren eyalkoren requested a review from SylvainJuge August 12, 2020 08:54
@videnkz
Copy link
Contributor Author

videnkz commented Aug 12, 2020

Awesome!! tada

Thanks you

@SylvainJuge SylvainJuge merged commit 30ba723 into elastic:master Aug 21, 2020
@ghost
Copy link

ghost commented Oct 20, 2020

Is there any way to disable these spans? They are taking a toll on our Elastic storage and we do not actually need them. I tried using the disable_instrumentations=servlet-api config but this causes the agent to not capture any page-load transactions anymore. Using spring-mvc here. Recently updated to 1.18.1 from 1.17.0.

@eyalkoren
Copy link
Contributor

Can you share numbers? How many such spans do you get per transaction?

@ghost
Copy link

ghost commented Oct 21, 2020

Hi @eyalkoren. We get from only a couple to more than a hundred. We had the same issue with spring-view-render and we were forced to stop instrumenting it. Once we did, the amount of used storage decreased to ~20GB per day, which was manageable. But now we have 140GB a day again, mostly jsp includes.

It is worth mentioning that we have lots of traffic.

I think the quick solution would be to downgrade to release 1.17.0 which was working fine for us.

@eyalkoren
Copy link
Contributor

@Purdel please try this snapshot with adding servlet-api-dispatch to the disable_instrumentations config and see if it works for you.
(I am looking into the test failures, but I don't think they are related).

@ghost
Copy link

ghost commented Oct 21, 2020

@eyalkoren wow, that was fast! Trying it out.

@ghost
Copy link

ghost commented Oct 21, 2020

@eyalkoren looks good

@eyalkoren
Copy link
Contributor

Awesome, thanks for verifying. #1448 is now merged.

@ghost
Copy link

ghost commented Oct 21, 2020

@eyalkoren great, thank you very much! Any idea when the next release will come?

@eyalkoren
Copy link
Contributor

I can't say exactly, but probably within a couple of weeks frame. You can register for notifications from our repo only on new releases.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

4 participants