Skip to content
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 deadline timeout for automatic transactions #2865

Merged
merged 8 commits into from
Aug 8, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,8 @@ Breaking changes:
- Set ip_address to {{auto}} by default, even if sendDefaultPII is disabled ([#2860](https://github.com/getsentry/sentry-java/pull/2860))
- Instead use the "Prevent Storing of IP Addresses" option in the "Security & Privacy" project settings on sentry.io
- Reduce timeout of AsyncHttpTransport to avoid ANR ([#2879](https://github.com/getsentry/sentry-java/pull/2879))
- Add deadline timeout for automatic transactions ([#2865](https://github.com/getsentry/sentry-java/pull/2865))
- This affects all automatically generated transactions on Android (UI, clicks), the default timeout is 30s

### Fixes

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -192,6 +192,9 @@ private void startTracing(final @NotNull Activity activity) {
final Boolean coldStart = AppStartState.getInstance().isColdStart();

final TransactionOptions transactionOptions = new TransactionOptions();
transactionOptions.setDeadlineTimeout(
TransactionOptions.DEFAULT_DEADLINE_TIMEOUT_AUTO_TRANSACTION);

if (options.isEnableActivityLifecycleTracingAutoFinish()) {
transactionOptions.setIdleTimeout(options.getIdleTimeout());
transactionOptions.setTrimEnd(true);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -237,6 +237,8 @@ private void startTracing(final @NotNull UiElement target, final @NotNull String

final TransactionOptions transactionOptions = new TransactionOptions();
transactionOptions.setWaitForChildren(true);
transactionOptions.setDeadlineTimeout(
TransactionOptions.DEFAULT_DEADLINE_TIMEOUT_AUTO_TRANSACTION);
transactionOptions.setIdleTimeout(options.getIdleTimeout());
transactionOptions.setTrimEnd(true);

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -43,7 +43,6 @@ import org.mockito.kotlin.clearInvocations
import org.mockito.kotlin.eq
import org.mockito.kotlin.mock
import org.mockito.kotlin.never
import org.mockito.kotlin.times
import org.mockito.kotlin.verify
import org.mockito.kotlin.whenever
import org.robolectric.Shadows.shadowOf
Expand Down Expand Up @@ -354,7 +353,7 @@ class ActivityLifecycleIntegrationTest {
}

@Test
fun `Transaction op is ui_load`() {
fun `Transaction op is ui_load and idle+deadline timeouts are set`() {
val sut = fixture.getSut()
fixture.options.tracesSampleRate = 1.0
sut.register(fixture.hub, fixture.options)
Expand All @@ -365,11 +364,14 @@ class ActivityLifecycleIntegrationTest {
sut.onActivityCreated(activity, fixture.bundle)

verify(fixture.hub).startTransaction(
check {
check<TransactionContext> {
assertEquals("ui.load", it.operation)
assertEquals(TransactionNameSource.COMPONENT, it.transactionNameSource)
},
any<TransactionOptions>()
check<TransactionOptions> { transactionOptions ->
assertEquals(fixture.options.idleTimeout, transactionOptions.idleTimeout)
assertEquals(TransactionOptions.DEFAULT_DEADLINE_TIMEOUT_AUTO_TRANSACTION, transactionOptions.deadlineTimeout)
}
)
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -206,6 +206,24 @@ class SentryGestureListenerTracingTest {
)
}

@Test
fun `captures transaction and both idle+deadline timeouts are set`() {
val sut = fixture.getSut<View>()

sut.onSingleTapUp(fixture.event)

verify(fixture.hub).startTransaction(
any<TransactionContext>(),
check<TransactionOptions> { transactionOptions ->
assertEquals(fixture.options.idleTimeout, transactionOptions.idleTimeout)
assertEquals(
TransactionOptions.DEFAULT_DEADLINE_TIMEOUT_AUTO_TRANSACTION,
transactionOptions.deadlineTimeout
)
}
)
}

@Test
fun `captures transaction with interaction event type as op`() {
val sut = fixture.getSut<View>()
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -132,15 +132,16 @@ class SentryNavigationListener @JvmOverloads constructor(
// we add '/' to the name to match dart and web pattern
name = "/" + name.substringBefore('/') // strip out arguments from the tx name

val transactonOptions = TransactionOptions().also {
val transactionOptions = TransactionOptions().also {
it.isWaitForChildren = true
it.idleTimeout = hub.options.idleTimeout
it.deadlineTimeout = TransactionOptions.DEFAULT_DEADLINE_TIMEOUT_AUTO_TRANSACTION
it.isTrimEnd = true
}

val transaction = hub.startTransaction(
TransactionContext(name, TransactionNameSource.ROUTE, NAVIGATION_OP),
transactonOptions
transactionOptions
)

transaction.spanContext.origin = traceOriginAppendix?.let {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -94,7 +94,12 @@ class SentryNavigationListenerTest {
whenever(context.resources).thenReturn(resources)
whenever(navController.context).thenReturn(context)
whenever(destination.route).thenReturn(toRoute)
return SentryNavigationListener(hub, enableBreadcrumbs, enableTracing, traceOriginAppendix)
return SentryNavigationListener(
hub,
enableBreadcrumbs,
enableTracing,
traceOriginAppendix
)
}
}

Expand Down Expand Up @@ -355,7 +360,8 @@ class SentryNavigationListenerTest {
fun `starts new trace if performance is disabled`() {
val sut = fixture.getSut(enableTracing = false)

val argumentCaptor: ArgumentCaptor<ScopeCallback> = ArgumentCaptor.forClass(ScopeCallback::class.java)
val argumentCaptor: ArgumentCaptor<ScopeCallback> =
ArgumentCaptor.forClass(ScopeCallback::class.java)
val scope = Scope(fixture.options)
val propagationContextAtStart = scope.propagationContext
whenever(fixture.hub.configureScope(argumentCaptor.capture())).thenAnswer {
Expand Down Expand Up @@ -385,4 +391,18 @@ class SentryNavigationListenerTest {

assertEquals("auto.navigation.jetpack_compose", fixture.transaction.spanContext.origin)
}

@Test
fun `Navigation listener transactions set automatic deadline timeout`() {
val sut = fixture.getSut()

sut.onDestinationChanged(fixture.navController, fixture.destination, null)

verify(fixture.hub).startTransaction(
any<TransactionContext>(),
check<TransactionOptions> { options ->
assertEquals(TransactionOptions.DEFAULT_DEADLINE_TIMEOUT_AUTO_TRANSACTION, options.deadlineTimeout)
}
)
}
}
3 changes: 3 additions & 0 deletions sentry/api/sentry.api
Original file line number Diff line number Diff line change
Expand Up @@ -2352,15 +2352,18 @@ public abstract interface class io/sentry/TransactionFinishedCallback {
}

public final class io/sentry/TransactionOptions : io/sentry/SpanOptions {
public static final field DEFAULT_DEADLINE_TIMEOUT_AUTO_TRANSACTION J
public fun <init> ()V
public fun getCustomSamplingContext ()Lio/sentry/CustomSamplingContext;
public fun getDeadlineTimeout ()Ljava/lang/Long;
public fun getIdleTimeout ()Ljava/lang/Long;
public fun getStartTimestamp ()Lio/sentry/SentryDate;
public fun getTransactionFinishedCallback ()Lio/sentry/TransactionFinishedCallback;
public fun isBindToScope ()Z
public fun isWaitForChildren ()Z
public fun setBindToScope (Z)V
public fun setCustomSamplingContext (Lio/sentry/CustomSamplingContext;)V
public fun setDeadlineTimeout (Ljava/lang/Long;)V
public fun setIdleTimeout (Ljava/lang/Long;)V
public fun setStartTimestamp (Lio/sentry/SentryDate;)V
public fun setTransactionFinishedCallback (Lio/sentry/TransactionFinishedCallback;)V
Expand Down
139 changes: 106 additions & 33 deletions sentry/src/main/java/io/sentry/SentryTracer.java
Original file line number Diff line number Diff line change
Expand Up @@ -37,10 +37,14 @@ public final class SentryTracer implements ITransaction {
*/
private @NotNull FinishStatus finishStatus = FinishStatus.NOT_FINISHED;

private volatile @Nullable TimerTask timerTask;
private volatile @Nullable TimerTask idleTimeoutTask;
private volatile @Nullable TimerTask deadlineTimeoutTask;

private volatile @Nullable Timer timer = null;
private final @NotNull Object timerLock = new Object();
private final @NotNull AtomicBoolean isFinishTimerRunning = new AtomicBoolean(false);

private final @NotNull AtomicBoolean isIdleFinishTimerRunning = new AtomicBoolean(false);
private final @NotNull AtomicBoolean isDeadlineTimerRunning = new AtomicBoolean(false);

private final @NotNull Baggage baggage;
private @NotNull TransactionNameSource transactionNameSource;
Expand Down Expand Up @@ -92,43 +96,59 @@ public SentryTracer(
transactionPerformanceCollector.start(this);
}

if (transactionOptions.getIdleTimeout() != null) {
if (transactionOptions.getIdleTimeout() != null
|| transactionOptions.getDeadlineTimeout() != null) {
timer = new Timer(true);

scheduleDeadlineTimeout();
scheduleFinish();
}
}

@Override
public void scheduleFinish() {
synchronized (timerLock) {
cancelTimer();
if (timer != null) {
isFinishTimerRunning.set(true);
timerTask =
new TimerTask() {
@Override
public void run() {
finishFromTimer();
}
};

try {
timer.schedule(timerTask, transactionOptions.getIdleTimeout());
} catch (Throwable e) {
hub.getOptions()
.getLogger()
.log(SentryLevel.WARNING, "Failed to schedule finish timer", e);
// if we failed to schedule the finish timer for some reason, we finish it here right away
finishFromTimer();
final @Nullable Long idleTimeout = transactionOptions.getIdleTimeout();

if (idleTimeout != null) {
cancelIdleTimer();
isIdleFinishTimerRunning.set(true);
idleTimeoutTask =
new TimerTask() {
@Override
public void run() {
onIdleTimeoutReached();
}
};

try {
timer.schedule(idleTimeoutTask, idleTimeout);
} catch (Throwable e) {
hub.getOptions()
.getLogger()
.log(SentryLevel.WARNING, "Failed to schedule finish timer", e);
// if we failed to schedule the finish timer for some reason, we finish it here right
// away
onIdleTimeoutReached();
}
}
}
}
}

private void finishFromTimer() {
final SpanStatus status = getStatus();
private void onIdleTimeoutReached() {
final @Nullable SpanStatus status = getStatus();
finish((status != null) ? status : SpanStatus.OK);
isFinishTimerRunning.set(false);
isIdleFinishTimerRunning.set(false);
}

private void onDeadlineTimeoutReached() {
final @Nullable SpanStatus status = getStatus();
forceFinish(
(status != null) ? status : SpanStatus.DEADLINE_EXCEEDED,
transactionOptions.getIdleTimeout() != null);
isDeadlineTimerRunning.set(false);
}

@Override
Expand Down Expand Up @@ -222,6 +242,8 @@ public void finish(
if (timer != null) {
synchronized (timerLock) {
if (timer != null) {
cancelIdleTimer();
cancelDeadlineTimer();
timer.cancel();
timer = null;
}
Expand All @@ -244,12 +266,51 @@ public void finish(
}
}

private void cancelTimer() {
private void cancelIdleTimer() {
synchronized (timerLock) {
if (timerTask != null) {
timerTask.cancel();
isFinishTimerRunning.set(false);
timerTask = null;
if (idleTimeoutTask != null) {
idleTimeoutTask.cancel();
isIdleFinishTimerRunning.set(false);
idleTimeoutTask = null;
}
}
}

private void scheduleDeadlineTimeout() {
final @Nullable Long deadlineTimeOut = transactionOptions.getDeadlineTimeout();
if (deadlineTimeOut != null) {
synchronized (timerLock) {
if (timer != null) {
cancelDeadlineTimer();
isDeadlineTimerRunning.set(true);
deadlineTimeoutTask =
new TimerTask() {
@Override
public void run() {
onDeadlineTimeoutReached();
}
};
try {
timer.schedule(deadlineTimeoutTask, deadlineTimeOut);
} catch (Throwable e) {
hub.getOptions()
.getLogger()
.log(SentryLevel.WARNING, "Failed to schedule finish timer", e);
// if we failed to schedule the finish timer for some reason, we finish it here right
// away
onDeadlineTimeoutReached();
}
}
}
}
}

private void cancelDeadlineTimer() {
synchronized (timerLock) {
if (deadlineTimeoutTask != null) {
deadlineTimeoutTask.cancel();
isDeadlineTimerRunning.set(false);
deadlineTimeoutTask = null;
}
}
}
Expand Down Expand Up @@ -360,7 +421,7 @@ private ISpan createChild(

Objects.requireNonNull(parentSpanId, "parentSpanId is required");
Objects.requireNonNull(operation, "operation is required");
cancelTimer();
cancelIdleTimer();
final Span span =
new Span(
root.getTraceId(),
Expand Down Expand Up @@ -720,8 +781,14 @@ Span getRoot() {

@TestOnly
@Nullable
TimerTask getTimerTask() {
return timerTask;
TimerTask getIdleTimeoutTask() {
return idleTimeoutTask;
}

@TestOnly
@Nullable
TimerTask getDeadlineTimeoutTask() {
return deadlineTimeoutTask;
}

@TestOnly
Expand All @@ -733,7 +800,13 @@ Timer getTimer() {
@TestOnly
@NotNull
AtomicBoolean isFinishTimerRunning() {
return isFinishTimerRunning;
return isIdleFinishTimerRunning;
}

@TestOnly
@NotNull
AtomicBoolean isDeadlineTimerRunning() {
return isDeadlineTimerRunning;
}

@TestOnly
Expand Down
Loading