From 813fd73e1252bb3126d033c62a3ba7427a335d2a Mon Sep 17 00:00:00 2001 From: Anuraag Agrawal Date: Fri, 26 Mar 2021 13:28:18 +0900 Subject: [PATCH 01/13] Enable strict context check and fix some context issues. --- gradle/java.gradle | 6 ++ .../javaagent/akka-http-10.0-javaagent.gradle | 4 ++ .../v2_2/TracingExecutionInterceptor.java | 8 +-- .../javaagent/executors-javaagent.gradle | 2 + .../RunnableInstrumentation.java | 2 +- .../javaagent/okhttp-2.2-javaagent.gradle | 2 - .../context/AgentContextStorage.java | 12 +++- .../TracingConsumeMessageHookImpl.java | 12 ++-- .../rocketmq/TracingSendMessageHookImpl.java | 18 +++--- .../scala-executors-javaagent.gradle | 4 ++ .../spring-webflux-5.0-javaagent.gradle | 1 + .../ExecutorInstrumentationUtils.java | 56 +++++++++++++------ .../test/InstrumentationSpecification.groovy | 8 +++ 13 files changed, 94 insertions(+), 41 deletions(-) diff --git a/gradle/java.gradle b/gradle/java.gradle index baae3d936c1b..c507e0b199ae 100644 --- a/gradle/java.gradle +++ b/gradle/java.gradle @@ -221,6 +221,12 @@ tasks.withType(Test).configureEach { testLogging { exceptionFormat = 'full' } + + // There's no real harm in setting this for all tests even if any happen to not be using context + // propagation. + jvmArgs "-Dio.opentelemetry.context.enableStrictContext=true" + // TODO(anuraaga): Have agent map unshaded to shaded. + jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=true" } tasks.withType(AbstractArchiveTask) { diff --git a/instrumentation/akka-http-10.0/javaagent/akka-http-10.0-javaagent.gradle b/instrumentation/akka-http-10.0/javaagent/akka-http-10.0-javaagent.gradle index a7846b594f92..891ee2a24016 100644 --- a/instrumentation/akka-http-10.0/javaagent/akka-http-10.0-javaagent.gradle +++ b/instrumentation/akka-http-10.0/javaagent/akka-http-10.0-javaagent.gradle @@ -62,3 +62,7 @@ compileVersion101TestGroovy { classpath = classpath.plus(files(compileVersion101TestScala.destinationDir)) dependsOn compileVersion101TestScala } + +tasks.withType(Test) { + jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" +} \ No newline at end of file diff --git a/instrumentation/aws-sdk/aws-sdk-2.2/library/src/main/java/io/opentelemetry/instrumentation/awssdk/v2_2/TracingExecutionInterceptor.java b/instrumentation/aws-sdk/aws-sdk-2.2/library/src/main/java/io/opentelemetry/instrumentation/awssdk/v2_2/TracingExecutionInterceptor.java index 9e650f3e4520..0a2096dedef8 100644 --- a/instrumentation/aws-sdk/aws-sdk-2.2/library/src/main/java/io/opentelemetry/instrumentation/awssdk/v2_2/TracingExecutionInterceptor.java +++ b/instrumentation/aws-sdk/aws-sdk-2.2/library/src/main/java/io/opentelemetry/instrumentation/awssdk/v2_2/TracingExecutionInterceptor.java @@ -128,10 +128,6 @@ private void populateGenericAttributes(Span span, ExecutionAttributes attributes @Override public void afterExecution( Context.AfterExecution context, ExecutionAttributes executionAttributes) { - Scope scope = executionAttributes.getAttribute(SCOPE_ATTRIBUTE); - if (scope != null) { - scope.close(); - } io.opentelemetry.context.Context otelContext = getContext(executionAttributes); clearAttributes(executionAttributes); Span span = Span.fromContext(otelContext); @@ -168,6 +164,10 @@ public void onExecutionFailure( } private void clearAttributes(ExecutionAttributes executionAttributes) { + Scope scope = executionAttributes.getAttribute(SCOPE_ATTRIBUTE); + if (scope != null) { + scope.close(); + } executionAttributes.putAttribute(CONTEXT_ATTRIBUTE, null); executionAttributes.putAttribute(AWS_SDK_REQUEST_ATTRIBUTE, null); } diff --git a/instrumentation/executors/javaagent/executors-javaagent.gradle b/instrumentation/executors/javaagent/executors-javaagent.gradle index 97205253a2fc..d6b68441f3f2 100644 --- a/instrumentation/executors/javaagent/executors-javaagent.gradle +++ b/instrumentation/executors/javaagent/executors-javaagent.gradle @@ -8,4 +8,6 @@ muzzle { tasks.withType(Test) { jvmArgs "-Dotel.instrumentation.executors.include=ExecutorInstrumentationTest\$CustomThreadPoolExecutor" + // NB(anuraaga): Unlike other similar exclusions this one does not seem to fail 100% of the time. + jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" } diff --git a/instrumentation/executors/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/javaconcurrent/RunnableInstrumentation.java b/instrumentation/executors/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/javaconcurrent/RunnableInstrumentation.java index 38a0d2652a5d..7dc161e226a2 100644 --- a/instrumentation/executors/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/javaconcurrent/RunnableInstrumentation.java +++ b/instrumentation/executors/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/javaconcurrent/RunnableInstrumentation.java @@ -47,7 +47,7 @@ public static Scope enter(@Advice.This Runnable thiz) { } @Advice.OnMethodExit(onThrowable = Throwable.class, suppress = Throwable.class) - public static void exit(@Advice.Enter Scope scope) { + public static void exit(@Advice.This Runnable thiz, @Advice.Enter Scope scope) { if (scope != null) { scope.close(); } diff --git a/instrumentation/okhttp/okhttp-2.2/javaagent/okhttp-2.2-javaagent.gradle b/instrumentation/okhttp/okhttp-2.2/javaagent/okhttp-2.2-javaagent.gradle index ac232a4aa091..5d7e35476462 100644 --- a/instrumentation/okhttp/okhttp-2.2/javaagent/okhttp-2.2-javaagent.gradle +++ b/instrumentation/okhttp/okhttp-2.2/javaagent/okhttp-2.2-javaagent.gradle @@ -18,5 +18,3 @@ dependencies { latestDepTestLibrary group: 'com.squareup.okhttp', name: 'okhttp', version: '[2.6,3)' } - - diff --git a/instrumentation/opentelemetry-api-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/opentelemetryapi/context/AgentContextStorage.java b/instrumentation/opentelemetry-api-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/opentelemetryapi/context/AgentContextStorage.java index 703b4d9a6b47..7fad21e4fa91 100644 --- a/instrumentation/opentelemetry-api-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/opentelemetryapi/context/AgentContextStorage.java +++ b/instrumentation/opentelemetry-api-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/opentelemetryapi/context/AgentContextStorage.java @@ -31,7 +31,7 @@ * always stores and retrieves them from the agent context, even when accessed from the application. * All other accesses are to the concrete application context. */ -public class AgentContextStorage implements ContextStorage { +public class AgentContextStorage implements ContextStorage, AutoCloseable { private static final Logger logger = LoggerFactory.getLogger(AgentContextStorage.class); @@ -145,6 +145,16 @@ public Context current() { return new AgentContextWrapper(io.opentelemetry.context.Context.current(), applicationContext); } + @Override + public void close() throws Exception { + io.opentelemetry.context.ContextStorage agentStorage = + io.opentelemetry.context.ContextStorage.get(); + System.out.println(agentStorage.getClass()); + if (agentStorage instanceof AutoCloseable) { + ((AutoCloseable) agentStorage).close(); + } + } + public static class AgentContextWrapper implements Context { private final io.opentelemetry.context.Context agentContext; private final Context applicationContext; diff --git a/instrumentation/rocketmq-client-4.8/library/src/main/java/io/opentelemetry/instrumentation/rocketmq/TracingConsumeMessageHookImpl.java b/instrumentation/rocketmq-client-4.8/library/src/main/java/io/opentelemetry/instrumentation/rocketmq/TracingConsumeMessageHookImpl.java index 11b0775a02cc..64ed0745b0db 100644 --- a/instrumentation/rocketmq-client-4.8/library/src/main/java/io/opentelemetry/instrumentation/rocketmq/TracingConsumeMessageHookImpl.java +++ b/instrumentation/rocketmq-client-4.8/library/src/main/java/io/opentelemetry/instrumentation/rocketmq/TracingConsumeMessageHookImpl.java @@ -27,9 +27,8 @@ public void consumeMessageBefore(ConsumeMessageContext context) { if (context == null || context.getMsgList() == null || context.getMsgList().isEmpty()) { return; } - Context traceContext = tracer.startSpan(Context.current(), context.getMsgList()); - ContextAndScope contextAndScope = new ContextAndScope(traceContext, traceContext.makeCurrent()); - context.setMqTraceContext(contextAndScope); + Context otelContext = tracer.startSpan(Context.current(), context.getMsgList()); + context.setMqTraceContext(otelContext); } @Override @@ -37,10 +36,9 @@ public void consumeMessageAfter(ConsumeMessageContext context) { if (context == null || context.getMsgList() == null || context.getMsgList().isEmpty()) { return; } - if (context.getMqTraceContext() instanceof ContextAndScope) { - ContextAndScope contextAndScope = (ContextAndScope) context.getMqTraceContext(); - contextAndScope.closeScope(); - tracer.end(contextAndScope.getContext()); + if (context.getMqTraceContext() instanceof Context) { + Context otelContext = (Context) context.getMqTraceContext(); + tracer.end(otelContext); } } } diff --git a/instrumentation/rocketmq-client-4.8/library/src/main/java/io/opentelemetry/instrumentation/rocketmq/TracingSendMessageHookImpl.java b/instrumentation/rocketmq-client-4.8/library/src/main/java/io/opentelemetry/instrumentation/rocketmq/TracingSendMessageHookImpl.java index 8665c3c9f36a..85ab6deb9be1 100644 --- a/instrumentation/rocketmq-client-4.8/library/src/main/java/io/opentelemetry/instrumentation/rocketmq/TracingSendMessageHookImpl.java +++ b/instrumentation/rocketmq-client-4.8/library/src/main/java/io/opentelemetry/instrumentation/rocketmq/TracingSendMessageHookImpl.java @@ -15,7 +15,7 @@ final class TracingSendMessageHookImpl implements SendMessageHook { private final RocketMqProducerTracer tracer; - private boolean propagationEnabled; + private final boolean propagationEnabled; TracingSendMessageHookImpl(RocketMqProducerTracer tracer, boolean propagationEnabled) { this.tracer = tracer; @@ -32,15 +32,14 @@ public void sendMessageBefore(SendMessageContext context) { if (context == null) { return; } - Context traceContext = + Context otelContext = tracer.startProducerSpan(Context.current(), context.getBrokerAddr(), context.getMessage()); if (propagationEnabled) { GlobalOpenTelemetry.getPropagators() .getTextMapPropagator() - .inject(traceContext, context.getMessage().getProperties(), SETTER); + .inject(otelContext, context.getMessage().getProperties(), SETTER); } - ContextAndScope contextAndScope = new ContextAndScope(traceContext, traceContext.makeCurrent()); - context.setMqTraceContext(contextAndScope); + context.setMqTraceContext(otelContext); } @Override @@ -48,11 +47,10 @@ public void sendMessageAfter(SendMessageContext context) { if (context == null || context.getMqTraceContext() == null || context.getSendResult() == null) { return; } - if (context.getMqTraceContext() instanceof ContextAndScope) { - ContextAndScope contextAndScope = (ContextAndScope) context.getMqTraceContext(); - tracer.afterProduce(contextAndScope.getContext(), context.getSendResult()); - contextAndScope.closeScope(); - tracer.end(contextAndScope.getContext()); + if (context.getMqTraceContext() instanceof Context) { + Context otelContext = (Context) context.getMqTraceContext(); + tracer.afterProduce(otelContext, context.getSendResult()); + tracer.end(otelContext); } } } diff --git a/instrumentation/scala-executors/javaagent/scala-executors-javaagent.gradle b/instrumentation/scala-executors/javaagent/scala-executors-javaagent.gradle index d0adf48e42d2..a784fd08f9fe 100644 --- a/instrumentation/scala-executors/javaagent/scala-executors-javaagent.gradle +++ b/instrumentation/scala-executors/javaagent/scala-executors-javaagent.gradle @@ -40,3 +40,7 @@ dependencies { // Run Slick library tests along with the rest of tests test.dependsOn slickTest + +tasks.withType(Test) { + jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" +} \ No newline at end of file diff --git a/instrumentation/spring/spring-webflux-5.0/javaagent/spring-webflux-5.0-javaagent.gradle b/instrumentation/spring/spring-webflux-5.0/javaagent/spring-webflux-5.0-javaagent.gradle index df3e71f68ef8..ff24928c3bf8 100644 --- a/instrumentation/spring/spring-webflux-5.0/javaagent/spring-webflux-5.0-javaagent.gradle +++ b/instrumentation/spring/spring-webflux-5.0/javaagent/spring-webflux-5.0-javaagent.gradle @@ -54,6 +54,7 @@ dependencies { tasks.withType(Test) { // TODO run tests both with and without experimental span attributes jvmArgs '-Dotel.instrumentation.spring-webflux.experimental-span-attributes=true' + jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" systemProperty "testLatestDeps", testLatestDeps } diff --git a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java index 4aac417704de..ea003ffda227 100644 --- a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java +++ b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java @@ -28,22 +28,46 @@ public static boolean shouldAttachStateToTask(Object task) { Class taskClass = task.getClass(); Class enclosingClass = taskClass.getEnclosingClass(); - // not much point in propagating root context - // plus it causes failures under otel.javaagent.testing.fail-on-context-leak=true - return Context.current() != Context.root() - // TODO Workaround for - // https://github.com/open-telemetry/opentelemetry-java-instrumentation/issues/787 - && !taskClass.getName().equals("org.apache.tomcat.util.net.NioEndpoint$SocketProcessor") - // Avoid context leak on jetty. Runnable submitted from SelectChannelEndPoint is used to - // process a new request which should not have context from them current request. - && (enclosingClass == null - || !enclosingClass.getName().equals("org.eclipse.jetty.io.nio.SelectChannelEndPoint")) - // Don't instrument the executor's own runnables. These runnables may never return until - // netty shuts down. - && (enclosingClass == null - || !enclosingClass - .getName() - .equals("io.netty.util.concurrent.SingleThreadEventExecutor")); + if (Context.current() == Context.root()) { + // not much point in propagating root context + // plus it causes failures under otel.javaagent.testing.fail-on-context-leak=true + return false; + } + + // TODO Workaround for + // https://github.com/open-telemetry/opentelemetry-java-instrumentation/issues/787 + if (taskClass.getName().equals("org.apache.tomcat.util.net.NioEndpoint$SocketProcessor")) { + return false; + } + + if (enclosingClass != null) { + // Avoid context leak on jetty. Runnable submitted from SelectChannelEndPoint is used to + // process a new request which should not have context from them current request. + if (enclosingClass.getName().equals("org.eclipse.jetty.io.nio.SelectChannelEndPoint")) { + return false; + } + + // Don't instrument the executor's own runnables. These runnables may never return until + // netty shuts down. + if (enclosingClass.getName().equals("io.netty.util.concurrent.SingleThreadEventExecutor")) { + return false; + } + + // OkHttp task runner is a lazily-initialized shared pool of continuosly running threads + // similar to an event loop. The submitted tasks themselves should already be instrumented to + // allow async propagation. + if (enclosingClass.getName().equals("okhttp3.internal.concurrent.TaskRunner")) { + return false; + } + + // OkHttp connection pool lazily initializes a long running task to detect expired connections + // and should not itself be instrumented. + if (enclosingClass.getName().equals("com.squareup.okhttp.ConnectionPool")) { + return false; + } + } + + return true; } /** diff --git a/testing-common/src/main/groovy/io/opentelemetry/instrumentation/test/InstrumentationSpecification.groovy b/testing-common/src/main/groovy/io/opentelemetry/instrumentation/test/InstrumentationSpecification.groovy index aa9e08d0418a..4d0fb870685b 100644 --- a/testing-common/src/main/groovy/io/opentelemetry/instrumentation/test/InstrumentationSpecification.groovy +++ b/testing-common/src/main/groovy/io/opentelemetry/instrumentation/test/InstrumentationSpecification.groovy @@ -9,6 +9,7 @@ import groovy.transform.stc.ClosureParams import groovy.transform.stc.SimpleType import io.opentelemetry.api.OpenTelemetry import io.opentelemetry.api.trace.Span +import io.opentelemetry.context.ContextStorage import io.opentelemetry.instrumentation.test.asserts.InMemoryExporterAssert import io.opentelemetry.instrumentation.testing.InstrumentationTestRunner import io.opentelemetry.instrumentation.testing.util.TelemetryDataUtil @@ -36,6 +37,13 @@ abstract class InstrumentationSpecification extends Specification { testRunner().clearAllExportedData() } + def cleanup() { + ContextStorage storage = ContextStorage.get() + if (storage instanceof AutoCloseable) { + ((AutoCloseable) storage).close() + } + } + def cleanupSpec() { testRunner().afterTestClass() } From 8a6fc392e1406fe1e5b01f89ac8574e04c1f9cc8 Mon Sep 17 00:00:00 2001 From: Anuraag Agrawal Date: Fri, 26 Mar 2021 14:18:54 +0900 Subject: [PATCH 02/13] Drift --- .../opentelemetryapi/context/AgentContextStorage.java | 1 - 1 file changed, 1 deletion(-) diff --git a/instrumentation/opentelemetry-api-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/opentelemetryapi/context/AgentContextStorage.java b/instrumentation/opentelemetry-api-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/opentelemetryapi/context/AgentContextStorage.java index 7fad21e4fa91..0f977a8332fc 100644 --- a/instrumentation/opentelemetry-api-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/opentelemetryapi/context/AgentContextStorage.java +++ b/instrumentation/opentelemetry-api-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/opentelemetryapi/context/AgentContextStorage.java @@ -149,7 +149,6 @@ public Context current() { public void close() throws Exception { io.opentelemetry.context.ContextStorage agentStorage = io.opentelemetry.context.ContextStorage.get(); - System.out.println(agentStorage.getClass()); if (agentStorage instanceof AutoCloseable) { ((AutoCloseable) agentStorage).close(); } From 55aa488b0b369cd7e169d64a237abde8a6bf91a6 Mon Sep 17 00:00:00 2001 From: Anuraag Agrawal Date: Fri, 26 Mar 2021 14:23:08 +0900 Subject: [PATCH 03/13] Drift and cache --- .../RunnableInstrumentation.java | 2 +- .../ExecutorInstrumentationUtils.java | 63 +++++++++++-------- 2 files changed, 39 insertions(+), 26 deletions(-) diff --git a/instrumentation/executors/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/javaconcurrent/RunnableInstrumentation.java b/instrumentation/executors/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/javaconcurrent/RunnableInstrumentation.java index 7dc161e226a2..38a0d2652a5d 100644 --- a/instrumentation/executors/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/javaconcurrent/RunnableInstrumentation.java +++ b/instrumentation/executors/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/javaconcurrent/RunnableInstrumentation.java @@ -47,7 +47,7 @@ public static Scope enter(@Advice.This Runnable thiz) { } @Advice.OnMethodExit(onThrowable = Throwable.class, suppress = Throwable.class) - public static void exit(@Advice.This Runnable thiz, @Advice.Enter Scope scope) { + public static void exit(@Advice.Enter Scope scope) { if (scope != null) { scope.close(); } diff --git a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java index ea003ffda227..cd8b7aafb258 100644 --- a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java +++ b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java @@ -14,6 +14,42 @@ /** Utils for concurrent instrumentations. */ public class ExecutorInstrumentationUtils { + private static final ClassValue NOT_INSTRUMENTED_RUNNABLE_ENCLOSING_CLASS = + new ClassValue() { + @Override + protected Boolean computeValue(Class enclosingClass) { + // Avoid context leak on jetty. Runnable submitted from SelectChannelEndPoint is used to + // process a new request which should not have context from them current request. + if (enclosingClass.getName().equals("org.eclipse.jetty.io.nio.SelectChannelEndPoint")) { + return true; + } + + // Don't instrument the executor's own runnables. These runnables may never return until + // netty shuts down. + if (enclosingClass + .getName() + .equals("io.netty.util.concurrent.SingleThreadEventExecutor")) { + return true; + } + + // OkHttp task runner is a lazily-initialized shared pool of continuosly running threads + // similar to an event loop. The submitted tasks themselves should already be instrumented + // to + // allow async propagation. + if (enclosingClass.getName().equals("okhttp3.internal.concurrent.TaskRunner")) { + return true; + } + + // OkHttp connection pool lazily initializes a long running task to detect expired + // connections + // and should not itself be instrumented. + if (enclosingClass.getName().equals("com.squareup.okhttp.ConnectionPool")) { + return true; + } + return false; + } + }; + /** * Checks if given task should get state attached. * @@ -40,31 +76,8 @@ public static boolean shouldAttachStateToTask(Object task) { return false; } - if (enclosingClass != null) { - // Avoid context leak on jetty. Runnable submitted from SelectChannelEndPoint is used to - // process a new request which should not have context from them current request. - if (enclosingClass.getName().equals("org.eclipse.jetty.io.nio.SelectChannelEndPoint")) { - return false; - } - - // Don't instrument the executor's own runnables. These runnables may never return until - // netty shuts down. - if (enclosingClass.getName().equals("io.netty.util.concurrent.SingleThreadEventExecutor")) { - return false; - } - - // OkHttp task runner is a lazily-initialized shared pool of continuosly running threads - // similar to an event loop. The submitted tasks themselves should already be instrumented to - // allow async propagation. - if (enclosingClass.getName().equals("okhttp3.internal.concurrent.TaskRunner")) { - return false; - } - - // OkHttp connection pool lazily initializes a long running task to detect expired connections - // and should not itself be instrumented. - if (enclosingClass.getName().equals("com.squareup.okhttp.ConnectionPool")) { - return false; - } + if (enclosingClass != null && NOT_INSTRUMENTED_RUNNABLE_ENCLOSING_CLASS.get(enclosingClass)) { + return false; } return true; From b97c6712d7d6fc8d10ff7076db91bcf068521816 Mon Sep 17 00:00:00 2001 From: Anuraag Agrawal Date: Fri, 26 Mar 2021 14:48:39 +0900 Subject: [PATCH 04/13] Exclude grizzly include akka --- .../javaagent/akka-http-10.0-javaagent.gradle | 4 ---- .../javaagent/executors-javaagent.gradle | 5 +++++ .../javaagent/grizzly-2.0-javaagent.gradle | 9 ++++++++- .../javaagent/scala-executors-javaagent.gradle | 4 ---- .../ExecutorInstrumentationUtils.java | 18 ++++++++++++++++++ 5 files changed, 31 insertions(+), 9 deletions(-) diff --git a/instrumentation/akka-http-10.0/javaagent/akka-http-10.0-javaagent.gradle b/instrumentation/akka-http-10.0/javaagent/akka-http-10.0-javaagent.gradle index 891ee2a24016..a7846b594f92 100644 --- a/instrumentation/akka-http-10.0/javaagent/akka-http-10.0-javaagent.gradle +++ b/instrumentation/akka-http-10.0/javaagent/akka-http-10.0-javaagent.gradle @@ -62,7 +62,3 @@ compileVersion101TestGroovy { classpath = classpath.plus(files(compileVersion101TestScala.destinationDir)) dependsOn compileVersion101TestScala } - -tasks.withType(Test) { - jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" -} \ No newline at end of file diff --git a/instrumentation/executors/javaagent/executors-javaagent.gradle b/instrumentation/executors/javaagent/executors-javaagent.gradle index d6b68441f3f2..cf9e99d9bbf3 100644 --- a/instrumentation/executors/javaagent/executors-javaagent.gradle +++ b/instrumentation/executors/javaagent/executors-javaagent.gradle @@ -9,5 +9,10 @@ muzzle { tasks.withType(Test) { jvmArgs "-Dotel.instrumentation.executors.include=ExecutorInstrumentationTest\$CustomThreadPoolExecutor" // NB(anuraaga): Unlike other similar exclusions this one does not seem to fail 100% of the time. + // + // java.lang.AssertionError: Thread [ForkJoinPool-11-worker-31] opened a scope of {opentelemetry-trace-span-key=RecordEventsReadableSpan{traceId=8fb08b7500b1b5f8fc1d5122d5f5636e, spanId=c641c53bbda41d28, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=parent, kind=INTERNAL, attributes=AttributesMap{data={thread.id=18, thread.name=Test worker}, capacity=128, totalAddedValues=2}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1616733793823002335, endEpochNanos=1616733793969157769}, otel-context=io.opentelemetry.javaagent.instrumentation.opentelemetryapi.context.AgentContextStorage$AgentContextWrapper@6c95888d, thread-propagation-locations=[[Ljava.lang.StackTraceElement;@6017e1d3]} here: + // at io.opentelemetry.javaagent.instrumentation.api.concurrent.AdviceUtils.startTaskScope(AdviceUtils.java:28) + // at JavaAsyncChild.exec(JavaAsyncChild.java:34) + // at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" } diff --git a/instrumentation/grizzly-2.0/javaagent/grizzly-2.0-javaagent.gradle b/instrumentation/grizzly-2.0/javaagent/grizzly-2.0-javaagent.gradle index 5f79087b6633..4f678f773083 100644 --- a/instrumentation/grizzly-2.0/javaagent/grizzly-2.0-javaagent.gradle +++ b/instrumentation/grizzly-2.0/javaagent/grizzly-2.0-javaagent.gradle @@ -22,4 +22,11 @@ dependencies { tasks.withType(Test) { jvmArgs "-Dotel.instrumentation.grizzly.enabled=true" -} \ No newline at end of file + // NB(anuraaga): Unlike other similar exclusions this one does not seem to fail 100% of the time. + // Stack trace that has been encountered is. + // + // java.lang.AssertionError: Thread [Grizzly-worker(2)] opened a scope of {opentelemetry-trace-span-key=RecordEventsReadableSpan{traceId=96b4747304733565aa64b063572bd8b0, spanId=5283bd8e13b286b2, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=HttpCodecFilter.handleRead, kind=SERVER, attributes=AttributesMap{data={http.url=http://localhost:11004/query?some=query, http.status_code=200, http.method=GET, net.peer.ip=127.0.0.1, thread.name=Grizzly-kernel(1) SelectorRunner, http.client_ip=1.1.1.1, net.peer.port=50786, thread.id=47, http.user_agent=test-user-agent, http.flavor=1.1}, capacity=128, totalAddedValues=10}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1616737327045001600, endEpochNanos=1616737327047716720}, opentelemetry-traces-server-span-key=RecordEventsReadableSpan{traceId=96b4747304733565aa64b063572bd8b0, spanId=5283bd8e13b286b2, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=HttpCodecFilter.handleRead, kind=SERVER, attributes=AttributesMap{data={http.url=http://localhost:11004/query?some=query, http.status_code=200, http.method=GET, net.peer.ip=127.0.0.1, thread.name=Grizzly-kernel(1) SelectorRunner, http.client_ip=1.1.1.1, net.peer.port=50786, thread.id=47, http.user_agent=test-user-agent, http.flavor=1.1}, capacity=128, totalAddedValues=10}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1616737327045001600, endEpochNanos=1616737327047716720}, thread-propagation-locations=[[Ljava.lang.StackTraceElement;@62b8a750, [Ljava.lang.StackTraceElement;@47209e45, [Ljava.lang.StackTraceElement;@210b05e3, [Ljava.lang.StackTraceElement;@2259d08f, [Ljava.lang.StackTraceElement;@61f7896b]} here: + // at io.opentelemetry.javaagent.instrumentation.api.concurrent.AdviceUtils.startTaskScope(AdviceUtils.java:28) + // at org.glassfish.grizzly.http.server.HttpHandler$1.run(HttpHandler.java:201) + jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" +} diff --git a/instrumentation/scala-executors/javaagent/scala-executors-javaagent.gradle b/instrumentation/scala-executors/javaagent/scala-executors-javaagent.gradle index a784fd08f9fe..d0adf48e42d2 100644 --- a/instrumentation/scala-executors/javaagent/scala-executors-javaagent.gradle +++ b/instrumentation/scala-executors/javaagent/scala-executors-javaagent.gradle @@ -40,7 +40,3 @@ dependencies { // Run Slick library tests along with the rest of tests test.dependsOn slickTest - -tasks.withType(Test) { - jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" -} \ No newline at end of file diff --git a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java index cd8b7aafb258..ad13bf5f9874 100644 --- a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java +++ b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java @@ -46,6 +46,7 @@ protected Boolean computeValue(Class enclosingClass) { if (enclosingClass.getName().equals("com.squareup.okhttp.ConnectionPool")) { return true; } + return false; } }; @@ -76,6 +77,23 @@ public static boolean shouldAttachStateToTask(Object task) { return false; } + // Long running task which decorates other tasks. We should probably be using ExecutionContext + // for propagation in Scala but in the meantime this is not needed along with other concurrent + // instrumentation and causes context leaks. + if (taskClass.getName().equals("akka.util.SerializedSuspendableExecutionContext")) { + return false; + } + + // Wrapper of tasks for dispatch - the wrapped task should have context already and this doesn't + // need it. It's not obvious why this simple wrapper (not long running task) could leak context. + // One hypothesis is Scala can rewrite any code to introduce suspend / resume, including the + // standard Runnable.run. If so, then this check should be generalized to exclude all Scala + // classes because it is never safe to make context active in a code that has a chance to + // suspend. + if (taskClass.getName().equals("akka.dispatch.TaskInvocation")) { + return false; + } + if (enclosingClass != null && NOT_INSTRUMENTED_RUNNABLE_ENCLOSING_CLASS.get(enclosingClass)) { return false; } From be6137315b37375347f7a1bc20d978c52fbae390 Mon Sep 17 00:00:00 2001 From: Anuraag Agrawal Date: Fri, 26 Mar 2021 15:08:26 +0900 Subject: [PATCH 05/13] Grizzly, scala --- .../javaagent/grizzly-2.0-javaagent.gradle | 9 +-------- .../concurrent/ExecutorInstrumentationUtils.java | 14 ++++++++++++++ 2 files changed, 15 insertions(+), 8 deletions(-) diff --git a/instrumentation/grizzly-2.0/javaagent/grizzly-2.0-javaagent.gradle b/instrumentation/grizzly-2.0/javaagent/grizzly-2.0-javaagent.gradle index 4f678f773083..5f79087b6633 100644 --- a/instrumentation/grizzly-2.0/javaagent/grizzly-2.0-javaagent.gradle +++ b/instrumentation/grizzly-2.0/javaagent/grizzly-2.0-javaagent.gradle @@ -22,11 +22,4 @@ dependencies { tasks.withType(Test) { jvmArgs "-Dotel.instrumentation.grizzly.enabled=true" - // NB(anuraaga): Unlike other similar exclusions this one does not seem to fail 100% of the time. - // Stack trace that has been encountered is. - // - // java.lang.AssertionError: Thread [Grizzly-worker(2)] opened a scope of {opentelemetry-trace-span-key=RecordEventsReadableSpan{traceId=96b4747304733565aa64b063572bd8b0, spanId=5283bd8e13b286b2, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=HttpCodecFilter.handleRead, kind=SERVER, attributes=AttributesMap{data={http.url=http://localhost:11004/query?some=query, http.status_code=200, http.method=GET, net.peer.ip=127.0.0.1, thread.name=Grizzly-kernel(1) SelectorRunner, http.client_ip=1.1.1.1, net.peer.port=50786, thread.id=47, http.user_agent=test-user-agent, http.flavor=1.1}, capacity=128, totalAddedValues=10}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1616737327045001600, endEpochNanos=1616737327047716720}, opentelemetry-traces-server-span-key=RecordEventsReadableSpan{traceId=96b4747304733565aa64b063572bd8b0, spanId=5283bd8e13b286b2, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=HttpCodecFilter.handleRead, kind=SERVER, attributes=AttributesMap{data={http.url=http://localhost:11004/query?some=query, http.status_code=200, http.method=GET, net.peer.ip=127.0.0.1, thread.name=Grizzly-kernel(1) SelectorRunner, http.client_ip=1.1.1.1, net.peer.port=50786, thread.id=47, http.user_agent=test-user-agent, http.flavor=1.1}, capacity=128, totalAddedValues=10}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1616737327045001600, endEpochNanos=1616737327047716720}, thread-propagation-locations=[[Ljava.lang.StackTraceElement;@62b8a750, [Ljava.lang.StackTraceElement;@47209e45, [Ljava.lang.StackTraceElement;@210b05e3, [Ljava.lang.StackTraceElement;@2259d08f, [Ljava.lang.StackTraceElement;@61f7896b]} here: - // at io.opentelemetry.javaagent.instrumentation.api.concurrent.AdviceUtils.startTaskScope(AdviceUtils.java:28) - // at org.glassfish.grizzly.http.server.HttpHandler$1.run(HttpHandler.java:201) - jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" -} +} \ No newline at end of file diff --git a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java index ad13bf5f9874..478282b83950 100644 --- a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java +++ b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java @@ -47,6 +47,15 @@ protected Boolean computeValue(Class enclosingClass) { return true; } + // The Grizzly HTTP handler seems to be run within the context of a request which can be + // suspended causing a different request to be executed. Assuming our tests are complete, + // it does not seem to be required to propagate context into this task. + // + // https://github.com/eclipse-ee4j/grizzly/blob/a2ce7775658e11fbccbb9acd32e2daf2b0799f45/modules/http-server/src/main/java/org/glassfish/grizzly/http/server/HttpHandler.java#L178 + if (enclosingClass.getName().equals("org.glassfish.grizzly.http.serve.HttpHandler")) { + return true; + } + return false; } }; @@ -94,6 +103,11 @@ public static boolean shouldAttachStateToTask(Object task) { return false; } + // See above. + if (taskClass.getName().equals("scala.concurrent.impl.Future$PromiseCompletingRunnable")) { + return false; + } + if (enclosingClass != null && NOT_INSTRUMENTED_RUNNABLE_ENCLOSING_CLASS.get(enclosingClass)) { return false; } From b2232ce5d29c736f2c892880c1c42d9c32eddf42 Mon Sep 17 00:00:00 2001 From: Anuraag Agrawal Date: Fri, 26 Mar 2021 15:19:10 +0900 Subject: [PATCH 06/13] ForkJoin worker --- .../executors/javaagent/executors-javaagent.gradle | 7 ------- .../api/concurrent/ExecutorInstrumentationUtils.java | 7 +++++++ 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/instrumentation/executors/javaagent/executors-javaagent.gradle b/instrumentation/executors/javaagent/executors-javaagent.gradle index cf9e99d9bbf3..97205253a2fc 100644 --- a/instrumentation/executors/javaagent/executors-javaagent.gradle +++ b/instrumentation/executors/javaagent/executors-javaagent.gradle @@ -8,11 +8,4 @@ muzzle { tasks.withType(Test) { jvmArgs "-Dotel.instrumentation.executors.include=ExecutorInstrumentationTest\$CustomThreadPoolExecutor" - // NB(anuraaga): Unlike other similar exclusions this one does not seem to fail 100% of the time. - // - // java.lang.AssertionError: Thread [ForkJoinPool-11-worker-31] opened a scope of {opentelemetry-trace-span-key=RecordEventsReadableSpan{traceId=8fb08b7500b1b5f8fc1d5122d5f5636e, spanId=c641c53bbda41d28, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=parent, kind=INTERNAL, attributes=AttributesMap{data={thread.id=18, thread.name=Test worker}, capacity=128, totalAddedValues=2}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1616733793823002335, endEpochNanos=1616733793969157769}, otel-context=io.opentelemetry.javaagent.instrumentation.opentelemetryapi.context.AgentContextStorage$AgentContextWrapper@6c95888d, thread-propagation-locations=[[Ljava.lang.StackTraceElement;@6017e1d3]} here: - // at io.opentelemetry.javaagent.instrumentation.api.concurrent.AdviceUtils.startTaskScope(AdviceUtils.java:28) - // at JavaAsyncChild.exec(JavaAsyncChild.java:34) - // at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) - jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" } diff --git a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java index 478282b83950..19c6ffeed605 100644 --- a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java +++ b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java @@ -80,6 +80,13 @@ public static boolean shouldAttachStateToTask(Object task) { return false; } + // ForkJoinPool threads are initialized lazily and continue to handle tasks similar to an event + // loop. They should not have context propagated to the base of the thread, tasks themselves + // will have it through other means. + if (taskClass.getName().equals("java.util.concurrent.ForkJoinWorkerThread")) { + return false; + } + // TODO Workaround for // https://github.com/open-telemetry/opentelemetry-java-instrumentation/issues/787 if (taskClass.getName().equals("org.apache.tomcat.util.net.NioEndpoint$SocketProcessor")) { From ecaa951d03cf0fca4d6c674474498a08bc400935 Mon Sep 17 00:00:00 2001 From: Anuraag Agrawal Date: Fri, 26 Mar 2021 15:34:02 +0900 Subject: [PATCH 07/13] webflux comment, grizzly typo --- .../javaagent/spring-webflux-5.0-javaagent.gradle | 4 ++++ .../api/concurrent/ExecutorInstrumentationUtils.java | 2 +- 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/instrumentation/spring/spring-webflux-5.0/javaagent/spring-webflux-5.0-javaagent.gradle b/instrumentation/spring/spring-webflux-5.0/javaagent/spring-webflux-5.0-javaagent.gradle index ff24928c3bf8..2f60345699d8 100644 --- a/instrumentation/spring/spring-webflux-5.0/javaagent/spring-webflux-5.0-javaagent.gradle +++ b/instrumentation/spring/spring-webflux-5.0/javaagent/spring-webflux-5.0-javaagent.gradle @@ -54,6 +54,10 @@ dependencies { tasks.withType(Test) { // TODO run tests both with and without experimental span attributes jvmArgs '-Dotel.instrumentation.spring-webflux.experimental-span-attributes=true' + // TODO(anuraaga): There is no actual context leak - it just seems that the server-side does not + // fully complete processing before the test cases finish, which is when we check for context + // leaks. Adding Thread.sleep(1000) just before checking for leaks allows it to pass but is not + // a good approach. Come up with a better one and enable this. jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" systemProperty "testLatestDeps", testLatestDeps diff --git a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java index 19c6ffeed605..07c4f77a799f 100644 --- a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java +++ b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java @@ -52,7 +52,7 @@ protected Boolean computeValue(Class enclosingClass) { // it does not seem to be required to propagate context into this task. // // https://github.com/eclipse-ee4j/grizzly/blob/a2ce7775658e11fbccbb9acd32e2daf2b0799f45/modules/http-server/src/main/java/org/glassfish/grizzly/http/server/HttpHandler.java#L178 - if (enclosingClass.getName().equals("org.glassfish.grizzly.http.serve.HttpHandler")) { + if (enclosingClass.getName().equals("org.glassfish.grizzly.http.server.HttpHandler")) { return true; } From e49eef7f2c935c6648acbbb3d32e90e0887d1fe2 Mon Sep 17 00:00:00 2001 From: Anuraag Agrawal Date: Fri, 26 Mar 2021 15:42:01 +0900 Subject: [PATCH 08/13] Give up on akka for now --- .../javaagent/akka-http-10.0-javaagent.gradle | 5 +++++ .../ExecutorInstrumentationUtils.java | 22 ------------------- 2 files changed, 5 insertions(+), 22 deletions(-) diff --git a/instrumentation/akka-http-10.0/javaagent/akka-http-10.0-javaagent.gradle b/instrumentation/akka-http-10.0/javaagent/akka-http-10.0-javaagent.gradle index a7846b594f92..f3ca5270ff0b 100644 --- a/instrumentation/akka-http-10.0/javaagent/akka-http-10.0-javaagent.gradle +++ b/instrumentation/akka-http-10.0/javaagent/akka-http-10.0-javaagent.gradle @@ -62,3 +62,8 @@ compileVersion101TestGroovy { classpath = classpath.plus(files(compileVersion101TestScala.destinationDir)) dependsOn compileVersion101TestScala } + +tasks.withType(Test) { + // https://github.com/open-telemetry/opentelemetry-java-instrumentation/issues/2639 + jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" +} \ No newline at end of file diff --git a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java index 07c4f77a799f..1312e0a48043 100644 --- a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java +++ b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java @@ -93,28 +93,6 @@ public static boolean shouldAttachStateToTask(Object task) { return false; } - // Long running task which decorates other tasks. We should probably be using ExecutionContext - // for propagation in Scala but in the meantime this is not needed along with other concurrent - // instrumentation and causes context leaks. - if (taskClass.getName().equals("akka.util.SerializedSuspendableExecutionContext")) { - return false; - } - - // Wrapper of tasks for dispatch - the wrapped task should have context already and this doesn't - // need it. It's not obvious why this simple wrapper (not long running task) could leak context. - // One hypothesis is Scala can rewrite any code to introduce suspend / resume, including the - // standard Runnable.run. If so, then this check should be generalized to exclude all Scala - // classes because it is never safe to make context active in a code that has a chance to - // suspend. - if (taskClass.getName().equals("akka.dispatch.TaskInvocation")) { - return false; - } - - // See above. - if (taskClass.getName().equals("scala.concurrent.impl.Future$PromiseCompletingRunnable")) { - return false; - } - if (enclosingClass != null && NOT_INSTRUMENTED_RUNNABLE_ENCLOSING_CLASS.get(enclosingClass)) { return false; } From 9d5adcdb115cec721ec0695460f2415b4a62f076 Mon Sep 17 00:00:00 2001 From: Anuraag Agrawal Date: Fri, 26 Mar 2021 15:59:06 +0900 Subject: [PATCH 09/13] threadpool --- .../api/concurrent/ExecutorInstrumentationUtils.java | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java index 1312e0a48043..78754ca6a59b 100644 --- a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java +++ b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java @@ -87,6 +87,13 @@ public static boolean shouldAttachStateToTask(Object task) { return false; } + // ThreadPoolExecutor worker threads may be initialized lazily and manage interruption of other + // threads. The actual tasks being run on those threads will propagate context but we should not + // propagate onto this management thread. + if (taskClass.getName().equals("java.util.concurrent.ThreadPoolExecutor$Worker")) { + return false; + } + // TODO Workaround for // https://github.com/open-telemetry/opentelemetry-java-instrumentation/issues/787 if (taskClass.getName().equals("org.apache.tomcat.util.net.NioEndpoint$SocketProcessor")) { From be8bfe4ab20e188514d5dbfe2100c8cefe0665ec Mon Sep 17 00:00:00 2001 From: Anuraag Agrawal Date: Fri, 26 Mar 2021 16:35:58 +0900 Subject: [PATCH 10/13] Fallback on grizzly, wait for completion in executor cancellation tests --- .../test/groovy/ExecutorInstrumentationTest.groovy | 12 +++++++++--- .../javaagent/grizzly-2.0-javaagent.gradle | 5 +++++ .../groovy/ScalaExecutorInstrumentationTest.groovy | 8 +++++++- .../api/concurrent/ExecutorInstrumentationUtils.java | 9 --------- 4 files changed, 21 insertions(+), 13 deletions(-) diff --git a/instrumentation/executors/javaagent/src/test/groovy/ExecutorInstrumentationTest.groovy b/instrumentation/executors/javaagent/src/test/groovy/ExecutorInstrumentationTest.groovy index ad927ab5e72b..6f62ef1c92f8 100644 --- a/instrumentation/executors/javaagent/src/test/groovy/ExecutorInstrumentationTest.groovy +++ b/instrumentation/executors/javaagent/src/test/groovy/ExecutorInstrumentationTest.groovy @@ -13,6 +13,7 @@ import java.util.concurrent.ArrayBlockingQueue import java.util.concurrent.Callable import java.util.concurrent.CompletableFuture import java.util.concurrent.ExecutionException +import java.util.concurrent.ExecutorService import java.util.concurrent.ForkJoinPool import java.util.concurrent.ForkJoinTask import java.util.concurrent.Future @@ -134,7 +135,7 @@ class ExecutorInstrumentationTest extends AgentInstrumentationSpecification { def "#poolImpl '#name' wrap lambdas"() { setup: - def pool = poolImpl + ExecutorService pool = poolImpl def m = method def w = wrap @@ -160,7 +161,7 @@ class ExecutorInstrumentationTest extends AgentInstrumentationSpecification { } cleanup: - pool?.shutdown() + pool.shutdown() where: name | method | wrap | poolImpl @@ -173,7 +174,7 @@ class ExecutorInstrumentationTest extends AgentInstrumentationSpecification { def "#poolImpl '#name' reports after canceled jobs"() { setup: - def pool = poolImpl + ExecutorService pool = poolImpl def m = method List children = new ArrayList<>() List jobFutures = new ArrayList<>() @@ -216,6 +217,11 @@ class ExecutorInstrumentationTest extends AgentInstrumentationSpecification { expect: waitForTraces(1).size() == 1 + // Wait for shutdown since we didn't wait on task completion and want to confirm any pending + // ones clean up context. + pool.shutdown() + pool.awaitTermination(10, TimeUnit.SECONDS) + where: name | method | poolImpl "submit Runnable" | submitRunnable | new ThreadPoolExecutor(1, 1, 1000, TimeUnit.NANOSECONDS, new ArrayBlockingQueue(1)) diff --git a/instrumentation/grizzly-2.0/javaagent/grizzly-2.0-javaagent.gradle b/instrumentation/grizzly-2.0/javaagent/grizzly-2.0-javaagent.gradle index 5f79087b6633..5fba968521af 100644 --- a/instrumentation/grizzly-2.0/javaagent/grizzly-2.0-javaagent.gradle +++ b/instrumentation/grizzly-2.0/javaagent/grizzly-2.0-javaagent.gradle @@ -22,4 +22,9 @@ dependencies { tasks.withType(Test) { jvmArgs "-Dotel.instrumentation.grizzly.enabled=true" +} + +tasks.withType(Test) { + // https://github.com/open-telemetry/opentelemetry-java-instrumentation/issues/2640 + jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" } \ No newline at end of file diff --git a/instrumentation/scala-executors/javaagent/src/test/groovy/ScalaExecutorInstrumentationTest.groovy b/instrumentation/scala-executors/javaagent/src/test/groovy/ScalaExecutorInstrumentationTest.groovy index be7243675721..1c8235ef4339 100644 --- a/instrumentation/scala-executors/javaagent/src/test/groovy/ScalaExecutorInstrumentationTest.groovy +++ b/instrumentation/scala-executors/javaagent/src/test/groovy/ScalaExecutorInstrumentationTest.groovy @@ -10,6 +10,7 @@ import io.opentelemetry.instrumentation.test.AgentInstrumentationSpecification import java.lang.reflect.InvocationTargetException import java.util.concurrent.ArrayBlockingQueue import java.util.concurrent.Callable +import java.util.concurrent.ExecutorService import java.util.concurrent.Future import java.util.concurrent.RejectedExecutionException import java.util.concurrent.ThreadPoolExecutor @@ -87,7 +88,7 @@ class ScalaExecutorInstrumentationTest extends AgentInstrumentationSpecification def "#poolImpl '#name' reports after canceled jobs"() { setup: - def pool = poolImpl + ExecutorService pool = poolImpl def m = method List children = new ArrayList<>() List jobFutures = new ArrayList<>() @@ -129,6 +130,11 @@ class ScalaExecutorInstrumentationTest extends AgentInstrumentationSpecification expect: waitForTraces(1).size() == 1 + // Wait for shutdown to make sure any remaining tasks finish and cleanup context since we don't + // wait on the tasks. + pool.shutdown() + pool.awaitTermination(10, TimeUnit.SECONDS) + where: name | method | poolImpl "submit Runnable" | submitRunnable | new ForkJoinPool() diff --git a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java index 78754ca6a59b..9590ce8e723f 100644 --- a/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java +++ b/javaagent-api/src/main/java/io/opentelemetry/javaagent/instrumentation/api/concurrent/ExecutorInstrumentationUtils.java @@ -47,15 +47,6 @@ protected Boolean computeValue(Class enclosingClass) { return true; } - // The Grizzly HTTP handler seems to be run within the context of a request which can be - // suspended causing a different request to be executed. Assuming our tests are complete, - // it does not seem to be required to propagate context into this task. - // - // https://github.com/eclipse-ee4j/grizzly/blob/a2ce7775658e11fbccbb9acd32e2daf2b0799f45/modules/http-server/src/main/java/org/glassfish/grizzly/http/server/HttpHandler.java#L178 - if (enclosingClass.getName().equals("org.glassfish.grizzly.http.server.HttpHandler")) { - return true; - } - return false; } }; From 2d32b4e0de617e66042a2d3bc4016d035f319789 Mon Sep 17 00:00:00 2001 From: Anuraag Agrawal Date: Sat, 27 Mar 2021 17:23:58 +0900 Subject: [PATCH 11/13] Hystrix --- .../hystrix-1.4/javaagent/hystrix-1.4-javaagent.gradle | 1 + 1 file changed, 1 insertion(+) diff --git a/instrumentation/hystrix-1.4/javaagent/hystrix-1.4-javaagent.gradle b/instrumentation/hystrix-1.4/javaagent/hystrix-1.4-javaagent.gradle index e3c81f97df76..7f268f730bff 100644 --- a/instrumentation/hystrix-1.4/javaagent/hystrix-1.4-javaagent.gradle +++ b/instrumentation/hystrix-1.4/javaagent/hystrix-1.4-javaagent.gradle @@ -20,6 +20,7 @@ tasks.withType(Test) { jvmArgs "-Dotel.instrumentation.hystrix.experimental-span-attributes=true" // Disable so failure testing below doesn't inadvertently change the behavior. jvmArgs "-Dhystrix.command.default.circuitBreaker.enabled=false" + jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" // Uncomment for debugging: // jvmArgs "-Dhystrix.command.default.execution.timeout.enabled=false" From dd99146e7ac73d79cc31c6fbb370f6f9f8651d96 Mon Sep 17 00:00:00 2001 From: Anuraag Agrawal Date: Sat, 27 Mar 2021 18:18:08 +0900 Subject: [PATCH 12/13] ratpack --- .../ratpack-1.4/javaagent/ratpack-1.4-javaagent.gradle | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/instrumentation/ratpack-1.4/javaagent/ratpack-1.4-javaagent.gradle b/instrumentation/ratpack-1.4/javaagent/ratpack-1.4-javaagent.gradle index e20b2e29dd71..0e24619187e6 100644 --- a/instrumentation/ratpack-1.4/javaagent/ratpack-1.4-javaagent.gradle +++ b/instrumentation/ratpack-1.4/javaagent/ratpack-1.4-javaagent.gradle @@ -20,3 +20,7 @@ dependencies { testImplementation group: 'com.sun.activation', name: 'jakarta.activation', version: '1.2.2' } } + +tasks.withType(Test) { + jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" +} From b4b89ef726aeaa67994d76a102de9540fce47da5 Mon Sep 17 00:00:00 2001 From: Anuraag Agrawal Date: Mon, 29 Mar 2021 11:16:23 +0900 Subject: [PATCH 13/13] Cleanups --- .../javaagent/ratpack-1.4-javaagent.gradle | 1 + .../rocketmq/ContextAndScope.java | 27 ------------------- .../junit/InstrumentationExtension.java | 12 ++++++++- 3 files changed, 12 insertions(+), 28 deletions(-) delete mode 100644 instrumentation/rocketmq-client-4.8/library/src/main/java/io/opentelemetry/instrumentation/rocketmq/ContextAndScope.java diff --git a/instrumentation/ratpack-1.4/javaagent/ratpack-1.4-javaagent.gradle b/instrumentation/ratpack-1.4/javaagent/ratpack-1.4-javaagent.gradle index 0e24619187e6..73b74f530d59 100644 --- a/instrumentation/ratpack-1.4/javaagent/ratpack-1.4-javaagent.gradle +++ b/instrumentation/ratpack-1.4/javaagent/ratpack-1.4-javaagent.gradle @@ -22,5 +22,6 @@ dependencies { } tasks.withType(Test) { + // https://github.com/open-telemetry/opentelemetry-java-instrumentation/issues/2648 jvmArgs "-Dio.opentelemetry.javaagent.shaded.io.opentelemetry.context.enableStrictContext=false" } diff --git a/instrumentation/rocketmq-client-4.8/library/src/main/java/io/opentelemetry/instrumentation/rocketmq/ContextAndScope.java b/instrumentation/rocketmq-client-4.8/library/src/main/java/io/opentelemetry/instrumentation/rocketmq/ContextAndScope.java deleted file mode 100644 index aa67e1f4cde1..000000000000 --- a/instrumentation/rocketmq-client-4.8/library/src/main/java/io/opentelemetry/instrumentation/rocketmq/ContextAndScope.java +++ /dev/null @@ -1,27 +0,0 @@ -/* - * Copyright The OpenTelemetry Authors - * SPDX-License-Identifier: Apache-2.0 - */ - -package io.opentelemetry.instrumentation.rocketmq; - -import io.opentelemetry.context.Context; -import io.opentelemetry.context.Scope; - -final class ContextAndScope { - private final Context context; - private final Scope scope; - - public ContextAndScope(Context context, Scope scope) { - this.context = context; - this.scope = scope; - } - - public Context getContext() { - return context; - } - - public void closeScope() { - scope.close(); - } -} diff --git a/testing-common/src/main/java/io/opentelemetry/instrumentation/testing/junit/InstrumentationExtension.java b/testing-common/src/main/java/io/opentelemetry/instrumentation/testing/junit/InstrumentationExtension.java index d819d9fbcb30..2dd0af82c2d3 100644 --- a/testing-common/src/main/java/io/opentelemetry/instrumentation/testing/junit/InstrumentationExtension.java +++ b/testing-common/src/main/java/io/opentelemetry/instrumentation/testing/junit/InstrumentationExtension.java @@ -6,6 +6,7 @@ package io.opentelemetry.instrumentation.testing.junit; import io.opentelemetry.api.OpenTelemetry; +import io.opentelemetry.context.ContextStorage; import io.opentelemetry.instrumentation.testing.InstrumentationTestRunner; import io.opentelemetry.instrumentation.testing.util.TelemetryDataUtil; import io.opentelemetry.sdk.metrics.data.MetricData; @@ -14,12 +15,13 @@ import java.util.concurrent.TimeUnit; import java.util.concurrent.TimeoutException; import org.junit.jupiter.api.extension.AfterAllCallback; +import org.junit.jupiter.api.extension.AfterEachCallback; import org.junit.jupiter.api.extension.BeforeAllCallback; import org.junit.jupiter.api.extension.BeforeEachCallback; import org.junit.jupiter.api.extension.ExtensionContext; public abstract class InstrumentationExtension - implements BeforeAllCallback, BeforeEachCallback, AfterAllCallback { + implements BeforeAllCallback, BeforeEachCallback, AfterAllCallback, AfterEachCallback { private static final long DEFAULT_TRACE_WAIT_TIMEOUT_SECONDS = 20; private final InstrumentationTestRunner testRunner; @@ -38,6 +40,14 @@ public void beforeEach(ExtensionContext extensionContext) { testRunner.clearAllExportedData(); } + @Override + public void afterEach(ExtensionContext context) throws Exception { + ContextStorage storage = ContextStorage.get(); + if (storage instanceof AutoCloseable) { + ((AutoCloseable) storage).close(); + } + } + @Override public void afterAll(ExtensionContext extensionContext) { testRunner.afterTestClass();