search

open-telemetry / opentelemetry-java-instrumentation

OpenTelemetry auto-instrumentation and instrumentation libraries for Java
https://opentelemetry.io
Apache License 2.0
1.99k stars 868 forks source link

Java Agent 1.25 and above not creating span for methods annotated with WithSpan #10159

Closed jakub-pomykala closed 10 months ago

jakub-pomykala commented 11 months ago

Describe the bug

When using Java Agent 1.25 or above it does not generate an extra span for methods annotated with WithSpan

We have added the following wrapper to ElementMatcher.Junction<ClassLoader> classLoaderMatcher() in the AnnotationInstrumentationModule class:

public class LoggingElementMatcher<T> extends ElementMatcher.Junction.AbstractBase<T> implements ElementMatcher.Junction<T> {

  private final ElementMatcher.Junction<T> delegate;

  private static final Logger logger = Logger.getLogger(AgentBuilderUtil.class.getName());

  public LoggingElementMatcher(ElementMatcher.Junction<T> delegate) {
    this.delegate = delegate;
  }

  @Override
  public boolean matches(T target) {
    boolean match = delegate.matches(target);
    if (target.getClass().getName().equals("com.ibm.ws.classloading.internal.AppClassLoader")) {
      logger.info("Matching: " + target + "," + match);
    }
    return match;
  }

}

It seems like there is something going wrong in the AppClassLoader whilst it is carrying out the matching task. For EE 7 and EE 8 the match returned is “false” whereas we are expecting true in: 

return new LoggingElementMatcher<ClassLoader>(hasClassesNamed("application.io.opentelemetry.instrumentation.annotations.WithSpan"));

Steps to reproduce

This method should call this method which should generate an additional span.

Expected behavior

You can see what we are expecting here where we are checking for the spans returned from the application. We have currently implemented a workaround where we are still using Java Agent 1.19 for Java EE 7 and EE 8.

Actual behavior

The additional WithSpan Span is missing.

Javaagent or library instrumentation version

v1.25,v1.26,v1.27,v1.28,v1.29

Environment

JDK: IBM Semeru Runtime Open Edition 17.0.8.0 (build 17.0.8+7)

OS: macOS 14.2.1

Additional context

No response

laurit commented 11 months ago

@jakub-pomykala does this repro only with the open liberty test harness or is it possible to also repro it by deploying a war to liberty? Does it matter whether opnjdk or openj9 is used?

jakub-pomykala commented 11 months ago

Hi @laurit, you will be able to reproduce the issue by deploying a war to liberty and I do not think that openjdk vs openj9 matters.

laurit commented 11 months ago

@jakub-pomykala I failed to reproduce this. Could you provide a war that reproduces this? Perhaps the version of liberty also matters?

jakub-pomykala commented 11 months ago

@laurit I've zipped up a war for JEE7, a war for JEE9 and also the corresponding server.xml files too. warFiles.zip

The liberty version should not matter.

laurit commented 10 months ago

@jakub-pomykala I still wasn't able to reproduce. I used Launching defaultServer (Open Liberty 23.0.0.12/wlp-1.0.84.cl231220231127-1901) on OpenJDK 64-Bit Server VM, version 17.0.7+7 (en_US) along with current build of the agent (also tried 1.27.0). Deployed agentTestEE9.war using the corresponding configuration. On request to http://localhost:9080/agentTest/withspannonbean logging exporter prints out

[err] [otel.javaagent 2024-01-05 09:57:20:238 +0200] [Default Executor-thread-25] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'AgentTestResource.withSpanNonBeanMethod' : c29ffd1aa88dd48cfcbe7572c1915d0c 79fae865bbce0ee2 INTERNAL [tracer: io.opentelemetry.opentelemetry-instrumentation-annotations-1.16:1.33.0-alpha-SNAPSHOT] AttributesMap{data={thread.name=Default Executor-thread-25, thread.id=82, code.namespace=io.openliberty.microprofile.telemetry.internal.apps.agent.AgentTestResource, code.function=withSpanNonBeanMethod}, capacity=128, totalAddedValues=4}
[err] [otel.javaagent 2024-01-05 09:57:20:239 +0200] [Default Executor-thread-25] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'AgentTestResource.callNonBeanWithSpan' : c29ffd1aa88dd48cfcbe7572c1915d0c 9f69ff64fdd57e22 INTERNAL [tracer: io.opentelemetry.jaxrs-3.0-annotations:1.33.0-alpha-SNAPSHOT] AttributesMap{data={thread.name=Default Executor-thread-25, thread.id=82, code.namespace=io.openliberty.microprofile.telemetry.internal.apps.agent.AgentTestResource, code.function=callNonBeanWithSpan}, capacity=128, totalAddedValues=4}
[err] [otel.javaagent 2024-01-05 09:57:20:271 +0200] [Default Executor-thread-25] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'GET /agentTest/withspannonbean' : c29ffd1aa88dd48cfcbe7572c1915d0c 8df30dfee14dcf4b SERVER [tracer: io.opentelemetry.servlet-5.0:1.33.0-alpha-SNAPSHOT] AttributesMap{data={server.port=9080, url.scheme=http, thread.name=Default Executor-thread-25, http.response.status_code=200, thread.id=82, user_agent.original=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36, network.protocol.version=1.1, network.peer.port=60257, network.peer.address=127.0.0.1, server.address=localhost, url.path=/agentTest/withspannonbean, http.request.method=GET, http.route=/agentTest/withspannonbean}, capacity=128, totalAddedValues=13}

AgentTestResource.withSpanNonBeanMethod span is created by the @WithSpan instrumentation

jakub-pomykala commented 10 months ago

@laurit agentTestEE9.war works as expected. Could you please give agentTestEE7.war a go

laurit commented 10 months ago

@jakub-pomykala I downloaded the Jakarta EE 8 variant from https://openliberty.io/start/#downloads-pkg and used the agentTestEE7.war along with the configuration from serverEE7.xml but it didn't work correctly. Application fails to start with

[ERROR   ] SRVE0271E: Uncaught init() exception created by servlet [io.openliberty.microprofile.telemetry.internal.apps.agent.AgentTestResource] in application [agentTestEE7]: java.lang.NoClassDefFoundError: io/opentelemetry/api/trace/Tracer
    at java.base/java.lang.Class.getDeclaredFields0(Native Method)
    at java.base/java.lang.Class.privateGetDeclaredFields(Class.java:3297)
    at java.base/java.lang.Class.getDeclaredFields(Class.java:2371)
    at org.apache.cxf.common.util.ReflectionUtil$10.run(ReflectionUtil.java:176)
    at [internal classes]

[ERROR   ] SRVE0315E: An exception occurred: java.lang.Throwable: javax.servlet.ServletException: SRVE0207E: Uncaught initialization exception created by servlet
    at com.ibm.ws.webcontainer.webapp.WebApp.handleRequest(WebApp.java:5134)
    at [internal classes]
Caused by: javax.servlet.ServletException: SRVE0207E: Uncaught initialization exception created by servlet
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.init(ServletWrapper.java:370)
    ... 1 more
Caused by: java.lang.NoClassDefFoundError: io/opentelemetry/api/trace/Tracer
    at java.base/java.lang.Class.getDeclaredFields0(Native Method)
    at java.base/java.lang.Class.privateGetDeclaredFields(Class.java:3297)
    at java.base/java.lang.Class.getDeclaredFields(Class.java:2371)
    at org.apache.cxf.common.util.ReflectionUtil$10.run(ReflectionUtil.java:176)
    ... 1 more

I guess I'm missing whatever it is that provides the opentelemetry api

[ERROR   ] CWWKF0001E: A feature definition could not be found for javaee-7.0
[ERROR   ] CWWKF0001E: A feature definition could not be found for cdi-1.2
[ERROR   ] CWWKF0001E: A feature definition could not be found for jaxrs-2.0
[ERROR   ] CWWKF0001E: A feature definition could not be found for mptelemetry-1.1
[WARNING ] CWWKS3103W: There are no users defined for the BasicRegistry configuration of ID com.ibm.ws.security.registry.basic.config[basic].
[AUDIT   ] CWWKZ0058I: Monitoring dropins for applications.
[AUDIT   ] CWPKI0820A: The default keystore has been created using the 'keystore_password' environment variable.
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/jwt/
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/metrics/
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/health/
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/openapi/
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/ibm/api/
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/openapi/ui/
[WARNING ] CWNEN0047W: Resource annotations on the fields of the io.openliberty.microprofile.telemetry.internal.apps.agent.AgentTestResource class will be ignored. The annotations could not be obtained because of the exception : java.lang.NoClassDefFoundError: io/opentelemetry/api/trace/Tracer
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/agentTest/
[AUDIT   ] CWWKZ0001I: Application agentTestEE7 started in 1.587 seconds.
[AUDIT   ] CWWKF0012I: The server installed the following features: [appSecurity-2.0, cdi-2.0, concurrent-1.0, distributedMap-1.0, jaxrs-2.1, jaxrsClient-2.1, jndi-1.0, json-1.0, jsonp-1.1, jwt-1.0, microProfile-1.4, mpConfig-1.3, mpFaultTolerance-1.1, mpHealth-1.0, mpJwt-1.1, mpMetrics-1.1, mpOpenAPI-1.0, mpOpenTracing-1.1, mpRestClient-1.1, opentracing-1.1, servlet-4.0, ssl-1.0].
jakub-pomykala commented 10 months ago

@laurit Could you try using the following for the server.xml:

<?xml version="1.0" encoding="UTF-8"?>
<server description="new server">

    <featureManager>
        <feature>javaee-8.0</feature>
        <feature>microProfile-4.1</feature>
        <feature>jaxrs-2.0</feature>
        <feature>cdi-1.2</feature>
        <feature>mpTelemetry-1.1</feature>
    </featureManager>

    <basicRegistry id="basic" realm="BasicRealm">
    </basicRegistry>

    <httpEndpoint id="defaultHttpEndpoint"
                  httpPort="9090"
                  httpsPort="9443" />

    <applicationManager autoExpand="true"/>

    <webApplication contextRoot="/agentTest" location="agentTestEE7.war">
        <classloader apiTypeVisibility="+third-party"/>
    </webApplication>

    <ssl id="defaultSSLConfig" trustDefaultCerts="true" />
</server>

Also, did you include the following dependencies in your pom.xml? 

        <dependency>
            <groupId>io.opentelemetry</groupId>
            <artifactId>opentelemetry-api</artifactId>
            <version>1.26.0</version>
        </dependency>
        <dependency>
            <groupId>io.opentelemetry.instrumentation</groupId>
            <artifactId>opentelemetry-instrumentation-annotations</artifactId>
            <version>1.26.0</version>
        </dependency>

Also, what command did you use to run?

laurit commented 10 months ago

Could you try using the following for the server.xml:

Same error

Launching defaultServer (Open Liberty 23.0.0.12/wlp-1.0.84.cl231220231127-1901) on OpenJDK 64-Bit Server VM, version 17.0.7+7 (en_US)
[AUDIT   ] CWWKE0001I: The server defaultServer has been launched.
[ERROR   ] CWWKF0001E: A feature definition could not be found for cdi-1.2
[ERROR   ] CWWKF0001E: A feature definition could not be found for jaxrs-2.0
[ERROR   ] CWWKF0001E: A feature definition could not be found for mptelemetry-1.1
[WARNING ] CWWKS3103W: There are no users defined for the BasicRegistry configuration of ID com.ibm.ws.security.registry.basic.config[basic].
[AUDIT   ] CWWKZ0058I: Monitoring dropins for applications.
[AUDIT   ] CWPKI0820A: The default keystore has been created using the 'keystore_password' environment variable.
OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
[AUDIT   ] CWWKI0001I: The CORBA name server is now available at corbaloc:iiop:localhost:2809/NameService.
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/ibm/api/
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/openapi/ui/
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/openapi/
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/jwt/
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/health/
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/metrics/
[WARNING ] CWNEN0047W: Resource annotations on the fields of the io.openliberty.microprofile.telemetry.internal.apps.agent.AgentTestResource class will be ignored. The annotations could not be obtained because of the exception : java.lang.NoClassDefFoundError: io/opentelemetry/api/trace/Tracer
[AUDIT   ] CWWKT0016I: Web application available (default_host): http://localhost:9080/agentTest/
[AUDIT   ] CWWKZ0001I: Application agentTestEE7 started in 2.417 seconds.
[AUDIT   ] CWWKF0012I: The server installed the following features: [appClientSupport-1.0, appSecurity-2.0, appSecurity-3.0, batch-1.0, beanValidation-2.0, cdi-2.0, concurrent-1.0, distributedMap-1.0, ejb-3.2, ejbHome-3.2, ejbLite-3.2, ejbPersistentTimer-3.2, ejbRemote-3.2, el-3.0, j2eeManagement-1.1, jacc-1.5, jaspic-1.1, javaMail-1.6, javaee-8.0, jaxb-2.2, jaxrs-2.1, jaxrsClient-2.1, jaxws-2.2, jca-1.7, jcaInboundSecurity-1.0, jdbc-4.2, jms-2.0, jndi-1.0, jpa-2.2, jpaContainer-2.2, jsf-2.3, json-1.0, jsonb-1.0, jsonp-1.1, jsp-2.3, jwt-1.0, managedBeans-1.0, mdb-3.2, microProfile-4.1, monitor-1.0, mpConfig-2.0, mpFaultTolerance-3.0, mpHealth-3.1, mpJwt-1.2, mpMetrics-3.0, mpOpenAPI-2.0, mpOpenTracing-2.0, mpRestClient-2.0, opentracing-2.0, servlet-4.0, ssl-1.0, wasJmsClient-2.0, wasJmsSecurity-1.0, wasJmsServer-1.0, webProfile-8.0, websocket-1.1].
[AUDIT   ] CWWKF0011I: The defaultServer server is ready to run a smarter planet. The defaultServer server started in 7.106 seconds.
[ERROR   ] SRVE0271E: Uncaught init() exception created by servlet [io.openliberty.microprofile.telemetry.internal.apps.agent.AgentTestResource] in application [agentTestEE7]: java.lang.NoClassDefFoundError: io/opentelemetry/api/trace/Tracer
    at java.base/java.lang.Class.getDeclaredFields0(Native Method)
    at java.base/java.lang.Class.privateGetDeclaredFields(Class.java:3297)
    at java.base/java.lang.Class.getDeclaredFields(Class.java:2371)
    at org.apache.cxf.common.util.ReflectionUtil$10.run(ReflectionUtil.java:176)
    at [internal classes]

[ERROR   ] SRVE0315E: An exception occurred: java.lang.Throwable: javax.servlet.ServletException: SRVE0207E: Uncaught initialization exception created by servlet
    at com.ibm.ws.webcontainer.webapp.WebApp.handleRequest(WebApp.java:5134)
    at [internal classes]
Caused by: javax.servlet.ServletException: SRVE0207E: Uncaught initialization exception created by servlet
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.init(ServletWrapper.java:370)
    ... 1 more
Caused by: java.lang.NoClassDefFoundError: io/opentelemetry/api/trace/Tracer
    at java.base/java.lang.Class.getDeclaredFields0(Native Method)
    at java.base/java.lang.Class.privateGetDeclaredFields(Class.java:3297)
    at java.base/java.lang.Class.getDeclaredFields(Class.java:2371)
    at org.apache.cxf.common.util.ReflectionUtil$10.run(ReflectionUtil.java:176)
    ... 1 more

Also, did you include the following dependencies in your pom.xml?

No, I did not. I uses the war that you provided and it does not include these dependencies. I thought that not including these and relying on <classloader apiTypeVisibility="+third-party"/> is what causes the issue.

Also, what command did you use to run?

JVM_ARGS="-javaagent:.../opentelemetry-java-instrumentation/javaagent/build/libs/opentelemetry-javaagent-1.33.0-SNAPSHOT.jar -Dotel.traces.exporter=logging -Dotel.metrics.exporter=none -Dotel.logs.exporter=none" ./server run defaultServer

jakub-pomykala commented 10 months ago

@laurit could you please try again by downloading All GA Features variant for 23.0.0.12 (click here to download).

And with the following server.xml 

<?xml version="1.0" encoding="UTF-8"?>
<server description="new server">

    <featureManager>
        <feature>javaee-7.0</feature>
        <feature>microProfile-1.4</feature>
        <feature>jaxrs-2.0</feature>
        <feature>cdi-1.2</feature>
        <feature>mpTelemetry-1.1</feature>
    </featureManager>

    <basicRegistry id="basic" realm="BasicRealm">
    </basicRegistry>

    <httpEndpoint id="defaultHttpEndpoint"
                  httpPort="9090"
                  httpsPort="9443" />

    <applicationManager autoExpand="true"/>

    <webApplication contextRoot="/agentTest" location="agentTestEE7.war">
        <classloader apiTypeVisibility="+third-party"/>
    </webApplication>

    <ssl id="defaultSSLConfig" trustDefaultCerts="true" />
</server>

Sorry about this, we realised that the mpTelemetry-1.1 was not in the Jakarta EE 8 variant

laurit commented 10 months ago

As far as I understand https://github.com/open-telemetry/opentelemetry-java-instrumentation/tree/main/instrumentation/internal/internal-eclipse-osgi-3.6/javaagent prevents looking into dynamic imports while detecting whether instrumentation dependencies are present. Because of that the @WithSpan instrumentation is not enabled for that app.

jakub-pomykala commented 10 months ago

Hey @laurit we have found a workaround for now which is to add:

-Dotel.instrumentation.internal-eclipse-osgi.enabled=false

To your jvm.options.

laurit commented 10 months ago

@trask wdyt if we changed https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/478404539d3f2104b93a95451b828c136e62e309/instrumentation/internal/internal-eclipse-osgi-3.6/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/internal/osgi/EclipseOsgiInstrumentation.java#L49 to allow dynamic imports for some packages for example the one with WithSpan annotation?