-
Notifications
You must be signed in to change notification settings - Fork 33
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
Add support for tracing methods asynchronously #86
Merged
Merged
Changes from 7 commits
Commits
Show all changes
10 commits
Select commit
Hold shift + click to select a range
d4aaf6e
Add support for tracing methods asynchronously
HaloFour d5f71c7
Change async tracing strategy, expand unit tests to cover many more c…
HaloFour d2435e7
PR feedback
HaloFour c00cb5a
Revert to tracing a single span for async methods that remains open a…
HaloFour eb4c4cc
Refactoring and additional unit tests
HaloFour 126b77c
Some refactoring/renaming, convert from ServiceLoader to typesafe Config
HaloFour da4c4d0
More refactoring, cleanup
HaloFour 68a7245
Address comments
HaloFour f217beb
Removing ExecutionContext parameter from trait
HaloFour 943197d
Minor refactoring and comments to help clarify the async behavior in …
HaloFour File filter
Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -18,12 +18,17 @@ package com.comcast.money.aspectj | |
|
||
import com.comcast.money.annotations.{ Timed, Traced, TracedData } | ||
import com.comcast.money.core.internal.MDCSupport | ||
import com.comcast.money.core.{ Tracer, Money, SpecHelpers } | ||
import com.comcast.money.core.{ LogRecord, Money, SpecHelpers } | ||
import org.aspectj.lang.ProceedingJoinPoint | ||
import org.mockito.Mockito._ | ||
import org.scalatest._ | ||
import org.scalatest.concurrent.Eventually | ||
import org.scalatest.mock.MockitoSugar | ||
import org.slf4j.MDC | ||
|
||
import scala.concurrent.{ Await, Promise } | ||
import scala.concurrent.duration._ | ||
import scala.util.{ Failure, Try } | ||
|
||
class TraceAspectSpec extends WordSpec | ||
with GivenWhenThen with OneInstancePerTest with BeforeAndAfterEach with Matchers with MockitoSugar with Eventually | ||
|
@@ -76,6 +81,58 @@ class TraceAspectSpec extends WordSpec | |
throw new RuntimeException("not-ignored") | ||
} | ||
|
||
@Traced( | ||
value = "asyncMethodReturnsPromise", | ||
async = true | ||
) | ||
def asyncMethodReturnsPromise(promise: Promise[String]): Promise[String] = promise | ||
|
||
@Traced( | ||
value = "asyncMethodReturnsNull", | ||
async = true | ||
) | ||
def asyncMethodReturnsNull(): Promise[String] = null | ||
|
||
@Traced( | ||
value = "asyncMethodReturnsNonPromise", | ||
async = true | ||
) | ||
def asyncMethodReturnsNonPromise(): AnyRef = new Object | ||
|
||
@Traced( | ||
value = "asyncMethodThrowingException", | ||
async = true | ||
) | ||
def asyncMethodThrowingException(): AnyRef = { | ||
Thread.sleep(50) | ||
throw new RuntimeException() | ||
} | ||
|
||
@Traced( | ||
value = "asyncMethodWithIgnoredException", | ||
async = true, | ||
ignoredExceptions = Array(classOf[IllegalArgumentException]) | ||
) | ||
def asyncMethodWithIgnoredException(): AnyRef = { | ||
throw new IllegalArgumentException("ignored") | ||
} | ||
|
||
@Traced( | ||
value = "asyncMethodWithNonMatchingIgnoredException", | ||
async = true, | ||
ignoredExceptions = Array(classOf[IllegalArgumentException]) | ||
) | ||
def asyncMethodWithNonMatchingIgnoredException(): AnyRef = { | ||
throw new RuntimeException("not-ignored") | ||
} | ||
|
||
@Traced( | ||
value = "asyncMethodWithIgnoredException", | ||
async = true, | ||
ignoredExceptions = Array(classOf[IllegalArgumentException]) | ||
) | ||
def asyncMethodWithIgnoredException(promise: Promise[String]): Promise[String] = promise | ||
|
||
@Timed("methodWithTiming") | ||
def methodWithTiming() = { | ||
Thread.sleep(50) | ||
|
@@ -88,6 +145,7 @@ class TraceAspectSpec extends WordSpec | |
|
||
override def beforeEach() = { | ||
reset(mockMdcSupport) | ||
LogRecord.clear() | ||
} | ||
|
||
"TraceAspect" when { | ||
|
@@ -115,7 +173,7 @@ class TraceAspectSpec extends WordSpec | |
expectLogMessageContaining("methodThrowingException") | ||
|
||
And("a span-success is logged with a value of true") | ||
expectLogMessageContaining("span-success=true") | ||
expectLogMessageContaining("span-success=false") | ||
} | ||
"complete the trace with success for methods that throw ignored exceptions" in { | ||
Given("a method that throws an ignored exception") | ||
|
@@ -146,6 +204,141 @@ class TraceAspectSpec extends WordSpec | |
expectLogMessageContaining("span-success=false") | ||
} | ||
} | ||
"advising methods by tracing them with async flag" should { | ||
"handle async methods that return a future" in { | ||
Given("a method that returns a future") | ||
|
||
When("the method is invoked") | ||
val promise = Promise[String]() | ||
val future = asyncMethodReturnsPromise(promise) | ||
|
||
Then("the method execution is logged") | ||
dontExpectSpanInfoThat("is named asyncMethodReturnsPromise", _.name == "asyncMethodReturnsPromise") | ||
|
||
When("the future completes") | ||
promise.complete(Try("Success")) | ||
Await.ready(future.future, 500 millis) | ||
|
||
Then("the async execution is logged") | ||
expectSpanInfoThat("is named asyncMethodReturnsPromise", _.name == "asyncMethodReturnsPromise") | ||
} | ||
"handle async methods that return a failed future" in { | ||
Given("a method that returns a future") | ||
|
||
When("the method is invoked") | ||
val promise = Promise[String]() | ||
val future = asyncMethodReturnsPromise(promise) | ||
|
||
Then("the method execution is logged") | ||
dontExpectSpanInfoThat("is named asyncMethodReturnsPromise", _.name == "asyncMethodReturnsPromise") | ||
|
||
When("the future fails") | ||
promise.complete(Failure(new RuntimeException())) | ||
Await.ready(future.future, 500 millis) | ||
|
||
Then("the async execution is logged") | ||
expectSpanInfoThat("is named asyncMethodReturnsPromise and is not successful", span => | ||
span.name == "asyncMethodReturnsPromise" && !span.success()) | ||
} | ||
"handle async methods that return a failed future with ignored exception" in { | ||
Given("a method that returns a future") | ||
|
||
When("the method is invoked") | ||
val promise = Promise[String]() | ||
val future = asyncMethodWithIgnoredException(promise) | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. should |
||
|
||
Then("the method execution is logged") | ||
dontExpectSpanInfoThat("is named asyncMethodWithIgnoredException", _.name == "asyncMethodWithIgnoredException") | ||
|
||
When("the future fails") | ||
promise.complete(Failure(new IllegalArgumentException())) | ||
Await.ready(future.future, 500 millis) | ||
|
||
Then("the async execution is logged") | ||
expectSpanInfoThat("is named asyncMethodWithIgnoredException and is successful", span => | ||
span.name == "asyncMethodWithIgnoredException" && span.success()) | ||
} | ||
"handle async methods that return a failed future with exception not in ignored list" in { | ||
Given("a method that returns a future") | ||
|
||
When("the method is invoked") | ||
val promise = Promise[String]() | ||
val future = asyncMethodWithIgnoredException(promise) | ||
|
||
Then("the method execution is logged") | ||
dontExpectSpanInfoThat("is named asyncMethodWithIgnoredException", _.name == "asyncMethodWithIgnoredException") | ||
|
||
When("the future fails") | ||
promise.complete(Failure(new RuntimeException())) | ||
Await.ready(future.future, 500 millis) | ||
|
||
Then("the async execution is logged") | ||
expectSpanInfoThat("is named asyncMethodWithIgnoredException and is not successful", span => | ||
span.name == "asyncMethodWithIgnoredException" && !span.success()) | ||
} | ||
"handle async methods that return a null future" in { | ||
Given("a method that returns null") | ||
|
||
When("the method is invoked") | ||
val future = asyncMethodReturnsNull() | ||
|
||
Then("the method and future execution is logged") | ||
expectSpanInfoThat("is named asyncMethodReturnsNull", _.name == "asyncMethodReturnsNull") | ||
} | ||
"handle async methods that return a non-future" in { | ||
Given("a method that returns a non-future") | ||
|
||
When("the method is invoked") | ||
val promise = Promise[String]() | ||
val future = asyncMethodReturnsNonPromise() | ||
|
||
Then("the method and future execution is logged") | ||
expectSpanInfoThat("is named asyncMethodReturnsNonPromise", _.name == "asyncMethodReturnsNonPromise") | ||
} | ||
"complete the trace for methods that throw exceptions" in { | ||
Given("a method that throws an exception") | ||
|
||
When("the method is invoked") | ||
a[RuntimeException] should be thrownBy { | ||
asyncMethodThrowingException() | ||
} | ||
|
||
Then("the method execution is logged") | ||
expectSpanInfoThat("is named asyncMethodThrowingException", _.name == "asyncMethodThrowingException") | ||
|
||
And("a span-success is logged with a value of false") | ||
expectLogMessageContaining("span-success=false") | ||
} | ||
"complete the trace with success for methods that throw ignored exceptions" in { | ||
Given("a method that throws an ignored exception") | ||
|
||
When("the method is invoked") | ||
an[IllegalArgumentException] should be thrownBy { | ||
asyncMethodWithIgnoredException() | ||
} | ||
|
||
Then("the method execution is logged") | ||
expectSpanInfoThat("is named asyncMethodWithIgnoredException", _.name == "asyncMethodWithIgnoredException") | ||
|
||
And("a span-success is logged with a value of true") | ||
expectLogMessageContaining("span-success=true") | ||
} | ||
"complete the trace with failure for methods that throw exceptions that are not in ignored list" in { | ||
Given("a method that throws an ignored exception") | ||
|
||
When("the method is invoked") | ||
a[RuntimeException] should be thrownBy { | ||
asyncMethodWithNonMatchingIgnoredException() | ||
} | ||
|
||
Then("the method execution is logged") | ||
expectSpanInfoThat("is named asyncMethodWithNonMatchingIgnoredException", _.name == "asyncMethodWithNonMatchingIgnoredException") | ||
|
||
And("a span-success is logged with a value of false") | ||
expectLogMessageContaining("span-success=false") | ||
} | ||
|
||
} | ||
"advising methods that have parameters with the TracedData annotation" should { | ||
"record the value of the parameter in the trace" in { | ||
Given("a method that has arguments with the TraceData annotation") | ||
|
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
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.
As opposed to adding an async flag, with aspectj anyway we can add a different joinpoint / pointcut on functions with annotations
@Trace
that return a promise (I think). Have you tried that? Unsure off the top of my head if that would workThere 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.
That would probably work although might require some effort to avoid ambiguity with existing pointcut. The problem with that is that it locks it to supporting only specific types and there is a fairly wide ecosystem of these types out there since Java didn't add one offering a callback until Java 8.
Promise[T]
is quite specific to Scala and its uncommon to see in other Java libraries.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.
Right, I am unclear if it would work. Can we have a test where, if someone sets async to be true, on something that is not async, that everything still works?
Imagine
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.
Agreed, the tests are a little anemic right now. This PR is more a spike for the purpose of discussion.
I might need to approach the unit tests a little differently as they should validate that log records aren't written until the promise/future is complete and the current helper methods don't really lend themselves to that, short of waiting for a timeout to expire. I'm thinking of mocking the Tracer instead.
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.
The main test that I would like to try out is nested futures (futures with flatmaps).
When I worked with scala Futures in the past, the onComplete of a future was executed in odd ways.
Imagine you have 3 levels of functions / nested futures via flatmaps and maps. You create child spans at each level, so 3 levels deep in a span tree. The onComplete and context that was passed was "off".
Sorry I don't have more information, I have to check out your PR and try and re-create the issue I saw
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.
Also, I think your example is odd. Seems like you have a future that yields a future as a value. That doesn't seem like a valid use case. I am curious if some of the contrived tests I wrote are things that people would never write?
Certainly
.flatMap { x => Future { x + 1 } }
is validBut
Future { Future { x } }
is notThere 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.
Which example is that? I'm trying to duplicate (or at least reinterpret) the unit tests you had around traced futures. Some of the examples are contrived intentionally but I also wouldn't discount my flubbing things up. I've not had the luxury of dedicating my attention to this recently.
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 was playing with going down a path of having
TraceAspect
replace the existingSpan
with a wrapperAsyncSpan
which internally would use anAtomicInteger
as a reference counter. Invoking a terminal method onFuture
likeonComplete
would bump that counter up. When that callback would complete it would callstop
, which would decrease the counter, as would when the instrumented future completed. Only when the counter reached zero would the span actually be stopped. I don't think that's quite what you were talking about, though.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.
That’s a great idea!
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 was thinking that perhaps my old TraceAspect unit tests had test cases that were invalid.