open-telemetry / opentelemetry-java-instrumentation

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

Instrumentation for tomcat,servlet,spring-webflux disabled when using opentelemetry-javaagent for auto instrumentation #5885

Closed mdtamim closed 2 years ago

mdtamim commented 2 years ago

Hi,

I am recently seeing that when we are deploying application with opentelemetry-javaagent for auto instrumentation,trace and span ids are not getting logged.On enabling debug logs,we found that Instrumentation has been disabled.Here is one such debug log sample :

-- Loading instrumentation servlet [class io.opentelemetry.javaagent.instrumentation.servlet.v2_2.Servlet2InstrumentationModule]   | [otel.javaagent 2022-04-18 23:15:19:366 -0700] [main] DEBUG io.opentelemetry.javaagent.extension.instrumentation.InstrumentationModule - Instrumentation servlet is disabled   | [otel.javaagent 2022-04-18 23:15:19:366 -0700] [main] DEBUG io.opentelemetry.javaagent.tooling.instrumentation.InstrumentationLoader - Loading instrumentation tomcat [class io.opentelemetry.javaagent.instrumentation.tomcat.v7_0.Tomcat7InstrumentationModule]   | [otel.javaagent 2022-04-18 23:15:19:366 -0700] [main] DEBUG io.opentelemetry.javaagent.extension.instrumentation.InstrumentationModule - Instrumentation tomcat is disabled

But we are not setting any flags to disable instrumentation.On further debugging I found that when java agent is starting somehow its setting the instrumentation as false in system properties as below : Key : otel.instrumentation.tomcat.enabled , Value : false Its same for spring webflux,servlet and few more modules. Any idea where these values are being set?

mateuszrzeszutek commented 2 years ago

Hey @mdtamim ,

On further debugging I found that when java agent is starting somehow its setting the instrumentation as false in system properties as below : Key : otel.instrumentation.tomcat.enabled , Value : false Its same for spring webflux,servlet and few more modules. Any idea where these values are being set?

By default, only a few instrumentations are disabled: grizzly and JDBC DataSource instrumentation. Everything else is enabled by default.

Please check the environment variables that are being inherited by your java application process -- the javaagent can also be configured using env vars, maybe you have OTEL_INSTRUMENTATION_TOMCAT_ENABLED being set to false in your env.

mdtamim commented 2 years ago

Thanks @mateuszrzeszutek for your reply.We have checked and its no where disabled.Also,we have even tried passing these specific library instrumentation flags as true but on loggging system properties we saw that these flags are set back to false.Its strange and we are trying to debug where exactly in the code these flags are being set to false.I have setup the code of opentelemetry-instrumentation in my local.Is there anyplace in the code where these flags are being updated?

mateuszrzeszutek commented 2 years ago

Can you paste here all the javaagent configuration properties/env vars that you're setting?

mdtamim commented 2 years ago

@mateuszrzeszutek PFB all the system properties we set: -Xms2048m -Xmx2048m -XX:-UseParallelOldGC -XX:+UnlockExperimentalVMOptions -XX:+UseZGC -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=768m -Xlog:gc=debug:file=/tmp/gc.log:time,pid,tags -Dserver.tomcat.threads.max=200 -Dspring.profiles.active=e1 -Dio.opentelemetry.javaagent.slf4j.simpleLogger.defaultLogLevel=ERROR -Dotel.propagators=b3 -javaagent:/opt/app-root//ot_agent.jar

We dont set anything explicitly in environment properties for open telemetry.Just FYI,Opentelemetry was working properly for last one year.But suddenly without any code change,new deployments are not working ie..trace and span ids are not getting logged for few modules/servers like tomcat,netty,servlet.When I added some custom logs to log system properties in Open telemetry agent,I saw the instrumentation flag for specific libraries are set as false.We have some 10-15 services and most of them are behaving this way.We deploy our services on ECP cloud which is mantained by our infrastructure team and no way they will add additional properties related to open telemetry.They just provide infrastructure support.

trask commented 2 years ago

On further debugging I found that when java agent is starting somehow its setting the instrumentation as false in system properties as below : Key : otel.instrumentation.tomcat.enabled , Value : false

@mdtamim that is very strange indeed

properties can also be loaded from a properties file, but the location for that properties file has to be configured explicitly using -Dotel.javaagent.configuration-file or OTEL_JAVAAGENT_CONFIGURATION_FILE.

I would check the complete command line args via ps -ef to make sure nothing is sneaking in somewhere. I would also check /proc/<pid>/environ to check that no env vars are sneaking in somewhere.

mdtamim commented 2 years ago

@trask we are using ECP cloud which is kubernetes based.Below are the details 1.Environment properties (I have masked some of the properties) : PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/local/s2i HOSTNAME= LOGGING_TYPE=splunk NAMESPACE= NS_APP_ENV=blazegateway_blazegqlgway_e1 EPAAS_VERSION=3.11 EPAAS_ENV=e1 APP_NAME=blazegqlgway CARID=500001139 POD_IP= MONITORING_TYPE=dynatrace KUBERNETES_PORT_53_TCP= EGRESS_SVC_KL2RW_PORT_13189_TCP= EGRESS_SVC_NRSC2_PORT_443_TCP_PROTO=tcp EGRESS_SVC_R9FM8_PORT_9090_TCP_PROTO=tcp EGRESS_SVC_VMF6L_PORT_443_TCP_PORT=443 EGRESS_SVC_CHGCL_PORT_3306_TCP_PROTO=tcp KUBERNETES_PORT= EGRESS_SVC_DJDR7_PORT_443_TCP_PROTO=tcp EGRESS_SVC_95T2K_SERVICE_HOST= OPENSHIFT_BUILD_NAME=blazegqlgway-build-139 OPENSHIFT_BUILD_NAMESPACE=blazegateway ARTIFACT_URL= PAAS_BUILD_ID=*** container=oci HOME=/home/jboss JAVA_HOME=/usr/lib/jvm/java-11 JAVA_VENDOR=openjdk JAVA_VERSION=11 JBOSS_CONTAINER_OPENJDK_JDK_MODULE=/opt/jboss/container/openjdk/jdk AB_PROMETHEUS_JMX_EXPORTER_CONFIG=/opt/jboss/container/prometheus/etc/jmx-exporter-config.yaml JBOSS_CONTAINER_PROMETHEUS_MODULE=/opt/jboss/container/prometheus AB_JOLOKIA_AUTH_OPENSHIFT=true AB_JOLOKIA_HTTPS=true AB_JOLOKIA_PASSWORD_RANDOM=true JBOSS_CONTAINER_JOLOKIA_MODULE=/opt/jboss/container/jolokia JOLOKIA_VERSION=1.6.2 LD_PRELOAD=libnss_wrapper.so NSS_WRAPPER_GROUP=/etc/group NSS_WRAPPER_PASSWD=/home/jboss/passwd S2I_SOURCE_DEPLOYMENTS_FILTER=appBundle JBOSS_CONTAINER_S2I_CORE_MODULE=/opt/jboss/container/s2i/core/ JBOSS_CONTAINER_JAVA_PROXY_MODULE=/opt/jboss/container/java/proxy JBOSS_CONTAINER_JAVA_JVM_MODULE=/opt/jboss/container/java/jvm JBOSS_CONTAINER_MAVEN_36_MODULE=/opt/jboss/container/maven/36/ MAVEN_VERSION=3.6 JBOSS_CONTAINER_UTIL_LOGGING_MODULE=/opt/jboss/container/util/logging/ JBOSS_CONTAINER_MAVEN_DEFAULT_MODULE=/opt/jboss/container/maven/default/ JBOSS_CONTAINER_MAVEN_S2I_MODULE=/opt/jboss/container/maven/s2i JAVA_DATA_DIR=/deployments/data JBOSS_CONTAINER_JAVA_RUN_MODULE=/opt/jboss/container/java/run JBOSS_CONTAINER_JAVA_S2I_MODULE=/opt/jboss/container/java/s2i JBOSS_IMAGE_NAME=openjdk/openjdk-11-rhel7 JBOSS_IMAGE_VERSION=1.11 APP_ROOT=/opt/app-root/ DEPLOYMENT_DIR=/deployments MAVEN_S2I_ARTIFACT_DIRS=target/appBundle JDK_VERSION=11.0.7 LD_LIBRARY_PATH=/opt/crypto:/opt/crypto/hiped TZ=America/Phoenix HTTPS_PROXY=

Process details (ps -ef response):

ps -ef Your Request is in progress UID PID PPID C STIME TTY TIME CMD 1026040+ 1 0 0 Apr18 ? 00:23:22 /usr/bin/java -Xms477m -Xmx1907m -XX:+UseParallelGC -XX:MinHeapFreeRatio=10 -XX:MaxHeapFreeRatio=20 -XX:GCTimeRatio=4 -XX:AdaptiveSizePolicyWeight=90 -XX:ParallelGCThreads=1 -Djava.util.concurrent.ForkJoinPool.common.parallelism=1 -XX:CICompilerCount=2 -XX:+ExitOnOutOfMemoryError -Xms2048m -Xmx2048m -XX:-UseParallelGC -XX:+UnlockExperimentalVMOptions -XX:+UseZGC -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=768m -XX:+PrintFlagsFinal -Xlog:gc=debug:file=/tmp/gc.log:time,pid,tags -Dsidh_psf_spring_profile=e1 -Dspring.profiles.active=e1 -Dsidh_symmetric_cipher_key= -Dio.opentelemetry.javaagent.slf4j.simpleLogger.defaultLogLevel=DEBUG -Dotel.propagators=b3 -Dvaultsecrets=file:///opt/epaas/vault/secrets/ -javaagent:/opt/app-root//ot_agent.jar -jar /deployments/app.jar -Dfile.encoding=UTF-8 -Dotel.resource.attributes=service.name=blazegqlgway -Dotel.traces.exporter=logging -Dotel.metrics.exporter=none -Dvaultsecrets=file:///opt/epaas/vault/secrets/*** -Dotel.propagators=b3 1026040+ 117503 0 0 07:26 ? 00:00:00 ps -ef

Thanks

trask commented 2 years ago

@mdtamim hm, I don't see anything wrong there 🤔

the next thing I'd try is attaching debugger at startup:

-agentlib:jdwp="transport=dt_socket,server=y,suspend=y,address=5000"

(put this JVM arg before the -javaagent: arg so that it will pause before the javaagent loads)

and checking the value of:

System.getProperty("otel.instrumentation.tomcat.enabled")

before any code has run

mdtamim commented 2 years ago

@trask thanks for reverting.Before you provided the above solution,I already implemented another java agent just to log system properties and added before the opentelemetry java agent in JAVA OPTIONS.So that the javaagent which logs system properties is executed first and then the open telemetry agent.I found that the first java agent didnt log any properties related to disabling instrumentation properties.Only after opentelemetry agent started,the system properties(I added custom logs there in ot agent code) by it has instrumentation set as false.PFB :

#################Properties logged by Java Agent to log System properties before OT agent starts

SystemPropertiesLoggerJavaAgent Key :: java.util.concurrent.ForkJoinPool.common.parallelism Value :: 1 SystemPropertiesLoggerJavaAgent Key :: awt.toolkit Value :: sun.awt.X11.XToolkit SystemPropertiesLoggerJavaAgent Key :: java.specification.version Value :: 11 SystemPropertiesLoggerJavaAgent Key :: sun.cpu.isalist Value :: SystemPropertiesLoggerJavaAgent Key :: sun.jnu.encoding Value :: ANSI_X3.4-1968 SystemPropertiesLoggerJavaAgent Key :: java.class.path Value :: /deployments/app.jar SystemPropertiesLoggerJavaAgent Key :: java.vm.vendor Value :: Red Hat, Inc. SystemPropertiesLoggerJavaAgent Key :: sun.arch.data.model Value :: 64 SystemPropertiesLoggerJavaAgent Key :: java.vendor.url Value :: https://www.redhat.com/ SystemPropertiesLoggerJavaAgent Key :: user.timezone Value :: SystemPropertiesLoggerJavaAgent Key :: os.name Value :: Linux SystemPropertiesLoggerJavaAgent Key :: java.vm.specification.version Value :: 11 SystemPropertiesLoggerJavaAgent Key :: io.opentelemetry.javaagent.slf4j.simpleLogger.defaultLogLevel Value :: DEBUG SystemPropertiesLoggerJavaAgent Key :: sun.java.launcher Value :: SUN_STANDARD SystemPropertiesLoggerJavaAgent Key :: user.country Value :: US SystemPropertiesLoggerJavaAgent Key :: sun.boot.library.path Value :: /usr/lib/jvm/java-11-openjdk-11.0.14.1.1-1.el7_9.x86_64/lib SystemPropertiesLoggerJavaAgent Key :: vaultsecrets Value :: file:///opt/epaas/vault/secrets/ SystemPropertiesLoggerJavaAgent Key :: sun.java.command Value :: /deployments/app.jar -Dfile.encoding=UTF-8 -Dotel.resource.attributes=service.name=blazegqlgway -Dotel.traces.exporter=logging -Dotel.metrics.exporter=none -Dvaultsecrets=file:///opt/epaas/vault/secrets/ -Dotel.propagators=b3 SystemPropertiesLoggerJavaAgent Key :: jdk.debug Value :: release SystemPropertiesLoggerJavaAgent Key :: sun.cpu.endian Value :: little SystemPropertiesLoggerJavaAgent Key :: user.home Value :: ? SystemPropertiesLoggerJavaAgent Key :: user.language Value :: en SystemPropertiesLoggerJavaAgent Key :: java.specification.vendor Value :: Oracle Corporation SystemPropertiesLoggerJavaAgent Key :: java.version.date Value :: 2022-02-08 SystemPropertiesLoggerJavaAgent Key :: java.home Value :: /usr/lib/jvm/java-11-openjdk-11.0.14.1.1-1.el7_9.x86_64 SystemPropertiesLoggerJavaAgent Key :: spring.profiles.active Value :: e1 SystemPropertiesLoggerJavaAgent Key :: file.separator Value :: / SystemPropertiesLoggerJavaAgent Key :: line.separator Value :: SystemPropertiesLoggerJavaAgent Key :: java.specification.name Value :: Java Platform API Specification SystemPropertiesLoggerJavaAgent Key :: java.vm.specification.vendor Value :: Oracle Corporation SystemPropertiesLoggerJavaAgent Key :: java.awt.graphicsenv Value :: sun.awt.X11GraphicsEnvironment SystemPropertiesLoggerJavaAgent Key :: sun.management.compiler Value :: HotSpot 64-Bit Tiered Compilers SystemPropertiesLoggerJavaAgent Key :: java.security.manager Value :: SystemPropertiesLoggerJavaAgent Key :: java.runtime.version Value :: 11.0.14.1+1-LTS SystemPropertiesLoggerJavaAgent Key :: user.name Value :: ? SystemPropertiesLoggerJavaAgent Key :: path.separator Value :: : SystemPropertiesLoggerJavaAgent Key :: os.version Value :: 3.10.0-1160.59.1.el7.x86_64 SystemPropertiesLoggerJavaAgent Key :: otel.propagators Value :: b3 SystemPropertiesLoggerJavaAgent Key :: java.security.policy Value :: /opt/app-root//policy.all SystemPropertiesLoggerJavaAgent Key :: java.runtime.name Value :: OpenJDK Runtime Environment SystemPropertiesLoggerJavaAgent Key :: file.encoding Value :: ANSI_X3.4-1968 SystemPropertiesLoggerJavaAgent Key :: java.vm.name Value :: OpenJDK 64-Bit Server VM SystemPropertiesLoggerJavaAgent Key :: java.vendor.version Value :: 18.9 SystemPropertiesLoggerJavaAgent Key :: sidh_psf_spring_profile Value :: e1 SystemPropertiesLoggerJavaAgent Key :: java.vendor.url.bug Value :: https://bugzilla.redhat.com/enter_bug.cgi?product=Red%20Hat%20Enterprise%20Linux%207&component=java-11-openjdk SystemPropertiesLoggerJavaAgent Key :: java.io.tmpdir Value :: /tmp SystemPropertiesLoggerJavaAgent Key :: java.version Value :: 11.0.14.1 SystemPropertiesLoggerJavaAgent Key :: user.dir Value :: /deployments SystemPropertiesLoggerJavaAgent Key :: os.arch Value :: amd64 SystemPropertiesLoggerJavaAgent Key :: java.vm.specification.name Value :: Java Virtual Machine Specification SystemPropertiesLoggerJavaAgent Key :: java.awt.printerjob Value :: sun.print.PSPrinterJob SystemPropertiesLoggerJavaAgent Key :: sun.os.patch.level Value :: unknown SystemPropertiesLoggerJavaAgent Key :: java.library.path Value :: /opt/crypto:/opt/crypto/hiped:/usr/java/packages/lib:/usr/lib64:/lib64:/lib:/usr/lib SystemPropertiesLoggerJavaAgent Key :: java.vm.info Value :: mixed mode SystemPropertiesLoggerJavaAgent Key :: java.vendor Value :: Red Hat, Inc. SystemPropertiesLoggerJavaAgent Key :: java.vm.version Value :: 11.0.14.1+1-LTS SystemPropertiesLoggerJavaAgent Key :: sun.io.unicode.encoding Value :: UnicodeLittle SystemPropertiesLoggerJavaAgent Key :: java.class.version Value :: 55.0


################System properties logged inside Open telemetry Java Agent

OpenTelemetryJavaAgent :: Key :: java.util.concurrent.ForkJoinPool.common.parallelism :: Value :: 1 OpenTelemetryJavaAgent :: Key :: awt.toolkit :: Value :: sun.awt.X11.XToolkit OpenTelemetryJavaAgent :: Key :: java.specification.version :: Value :: 11 OpenTelemetryJavaAgent :: Key :: sun.cpu.isalist :: Value :: OpenTelemetryJavaAgent :: Key :: sun.jnu.encoding :: Value :: ANSI_X3.4-1968 OpenTelemetryJavaAgent :: Key :: otel.instrumentation.apache-httpclient.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: java.class.path :: Value :: /deployments/app.jar OpenTelemetryJavaAgent :: Key :: otel.instrumentation.jdbc-datasource.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: java.vm.vendor :: Value :: Red Hat, Inc. OpenTelemetryJavaAgent :: Key :: sun.arch.data.model :: Value :: 64 OpenTelemetryJavaAgent :: Key :: otel.instrumentation.jedis.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: otel.instrumentation.cxf.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: java.vendor.url :: Value :: https://www.redhat.com/ OpenTelemetryJavaAgent :: Key :: user.timezone :: Value :: OpenTelemetryJavaAgent :: Key :: otel.instrumentation.spring-webflux.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: otel.instrumentation.undertow.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: os.name :: Value :: Linux OpenTelemetryJavaAgent :: Key :: java.vm.specification.version :: Value :: 11 OpenTelemetryJavaAgent :: Key :: io.opentelemetry.javaagent.slf4j.simpleLogger.defaultLogLevel :: Value :: DEBUG OpenTelemetryJavaAgent :: Key :: sun.java.launcher :: Value :: SUN_STANDARD OpenTelemetryJavaAgent :: Key :: user.country :: Value :: US OpenTelemetryJavaAgent :: Key :: sun.boot.library.path :: Value :: /usr/lib/jvm/java-11-openjdk-11.0.14.1.1-1.el7_9.x86_64/lib OpenTelemetryJavaAgent :: Key :: vaultsecrets :: Value :: file:///opt/epaas/vault/secrets/*** OpenTelemetryJavaAgent :: Key :: sun.java.command :: Value :: /deployments/app.jar -Dfile.encoding=UTF-8 -Dotel.resource.attributes=service.name=blazegqlgway -Dotel.traces.exporter=logging -Dotel.metrics.exporter=none -Dvaultsecrets=file:///opt/epaas/vault/secrets/secrets -Dotel.propagators=b3 OpenTelemetryJavaAgent :: Key :: otel.instrumentation.jaxws.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: otel.instrumentation.jms.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: jdk.debug :: Value :: release OpenTelemetryJavaAgent :: Key :: sun.cpu.endian :: Value :: little OpenTelemetryJavaAgent :: Key :: user.home :: Value :: ? OpenTelemetryJavaAgent :: Key :: user.language :: Value :: en OpenTelemetryJavaAgent :: Key :: java.specification.vendor :: Value :: Oracle Corporation OpenTelemetryJavaAgent :: Key :: otel.instrumentation.kafka.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: java.version.date :: Value :: 2022-02-08 OpenTelemetryJavaAgent :: Key :: java.home :: Value :: /usr/lib/jvm/java-11-openjdk-11.0.14.1.1-1.el7_9.x86_64 OpenTelemetryJavaAgent :: Key :: spring.profiles.active :: Value :: e1 OpenTelemetryJavaAgent :: Key :: otel.instrumentation.liberty.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: file.separator :: Value :: / OpenTelemetryJavaAgent :: Key :: line.separator :: Value :: OpenTelemetryJavaAgent :: Key :: otel.instrumentation.jaxrs.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: java.specification.name :: Value :: Java Platform API Specification OpenTelemetryJavaAgent :: Key :: java.vm.specification.vendor :: Value :: Oracle Corporation OpenTelemetryJavaAgent :: Key :: java.awt.graphicsenv :: Value :: sun.awt.X11GraphicsEnvironment OpenTelemetryJavaAgent :: Key :: otel.instrumentation.grpc.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: otel.instrumentation.executor.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: otel.instrumentation.scala-executors.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: otel.instrumentation.async-http-client.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: otel.instrumentation.metro.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: sun.management.compiler :: Value :: HotSpot 64-Bit Tiered Compilers OpenTelemetryJavaAgent :: Key :: otel.instrumentation.java-http-client.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: otel.instrumentation.jdbc.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: java.security.manager :: Value :: OpenTelemetryJavaAgent :: Key :: java.runtime.version :: Value :: 11.0.14.1+1-LTS OpenTelemetryJavaAgent :: Key :: otel.instrumentation.akka-http.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: user.name :: Value :: ? OpenTelemetryJavaAgent :: Key :: path.separator :: Value :: : OpenTelemetryJavaAgent :: Key :: otel.instrumentation.jetty.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: os.version :: Value :: 3.10.0-1160.59.1.el7.x86_64 OpenTelemetryJavaAgent :: Key :: otel.propagators :: Value :: b3 OpenTelemetryJavaAgent :: Key :: java.security.policy :: Value :: /opt/app-root//policy.all OpenTelemetryJavaAgent :: Key :: otel.instrumentation.cassandra.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: java.runtime.name :: Value :: OpenJDK Runtime Environment OpenTelemetryJavaAgent :: Key :: otel.instrumentation.rabbitmq.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: file.encoding :: Value :: ANSI_X3.4-1968 OpenTelemetryJavaAgent :: Key :: otel.instrumentation.tomcat.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: otel.instrumentation.akka-actor.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: java.vm.name :: Value :: OpenJDK 64-Bit Server VM OpenTelemetryJavaAgent :: Key :: java.vendor.version :: Value :: 18.9 OpenTelemetryJavaAgent :: Key :: otel.instrumentation.apache-httpasyncclient.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: otel.instrumentation.mongo.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: otel.instrumentation.netty.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: otel.instrumentation.axis2.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: sidh_psf_spring_profile :: Value :: e1 OpenTelemetryJavaAgent :: Key :: java.vendor.url.bug :: Value :: https://bugzilla.redhat.com/enter_bug.cgi?product=Red%20Hat%20Enterprise%20Linux%207&component=java-11-openjdk OpenTelemetryJavaAgent :: Key :: java.io.tmpdir :: Value :: /tmp OpenTelemetryJavaAgent :: Key :: otel.instrumentation.rmi.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: java.version :: Value :: 11.0.14.1 OpenTelemetryJavaAgent :: Key :: user.dir :: Value :: /deployments OpenTelemetryJavaAgent :: Key :: os.arch :: Value :: amd64 OpenTelemetryJavaAgent :: Key :: java.vm.specification.name :: Value :: Java Virtual Machine Specification OpenTelemetryJavaAgent :: Key :: java.awt.printerjob :: Value :: sun.print.PSPrinterJob OpenTelemetryJavaAgent :: Key :: sun.os.patch.level :: Value :: unknown OpenTelemetryJavaAgent :: Key :: java.library.path :: Value :: /opt/crypto:/opt/crypto/hiped:/usr/java/packages/lib:/usr/lib64:/lib64:/lib:/usr/lib OpenTelemetryJavaAgent :: Key :: java.vm.info :: Value :: mixed mode OpenTelemetryJavaAgent :: Key :: java.vendor :: Value :: Red Hat, Inc. OpenTelemetryJavaAgent :: Key :: java.vm.version :: Value :: 11.0.14.1+1-LTS OpenTelemetryJavaAgent :: Key :: otel.instrumentation.http-url-connection.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: sun.io.unicode.encoding :: Value :: UnicodeLittle OpenTelemetryJavaAgent :: Key :: otel.instrumentation.spring-ws.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: java.class.version :: Value :: 55.0 OpenTelemetryJavaAgent :: Key :: otel.instrumentation.okhttp.enabled :: Value :: false OpenTelemetryJavaAgent :: Key :: otel.instrumentation.servlet.enabled :: Value :: false

Also I am adding these logs in startAgent method inside OpenTelemetryAgent class inside javaagent-bootstrap module.Below is the modification I did(please Ignore logging standard):


private static void startAgent(Instrumentation inst, boolean fromPremain) { try { System.getProperties().forEach((k,v)->System.out.println("OpenTelemetryAgent startAgent :: Key :: "+k+" :: Value :: "+v));//This line i added File javaagentFile = installBootstrapJar(inst); InstrumentationHolder.setInstrumentation(inst); AgentInitializer.initialize(inst, javaagentFile, fromPremain); } catch (Throwable ex) { // Don't rethrow. We don't have a log manager here, so just print. System.err.println("ERROR " + OpenTelemetryAgent.class.getName()); ex.printStackTrace(); } }


Thanks

trask commented 2 years ago

@mdtamim can you put a breakpoint in (or instrument) System.setProperty() to see who is calling it and updating those system property values?

mdtamim commented 2 years ago

I already checked this.Instrumentation flags are not being set to false using system.setProperties.Also fyi,it's working fine in local,in cloud it's behaving this way only in most services except a few.I checked even in cloud what properties are being set using System.setProperties but instrumentation flags are not among them.

mdtamim commented 2 years ago

Just to let you know,I took reference from below link to log when system.setProperties is called : https://stackoverflow.com/questions/10710450/how-to-detect-if-a-java-system-property-has-changed

laurit commented 2 years ago

This is strange. So you are saying that you added both your debug agent and modified opentelemetry agent to jvm arguments and debug agent didn't print out any otel.instrumentation.xxx.enabled properties while the debug logging in opentelemetry agent did? The place where you added debug logging in otel agent is run really early so otel agent really hasn't had a chance to do anything until that point so as far as I can tell these properties must have been set before the agent starts. What is fishy is that not all instrumentations seem to be disabled and an instrumentation that doesn't exist (scala-executors was renamed) is also disabled. You could try printing out System.getenv() similarly to what you do with System.getProperties() and see whether something is set in JAVA_TOOL_OPTIONS. Also it seems that you have added some of the jvm arguments after -jar /deployments/app.jar these will be treated as program arguments which is probably not what you want.

mateuszrzeszutek commented 2 years ago

@mdtamim Are you using the vanilla OTel javaagent? Or some vendor distribution? What version of the agent are you using?

mdtamim commented 2 years ago

So you are saying that you added both your debug agent and modified opentelemetry agent to jvm arguments and debug agent didn't print out any otel.instrumentation.xxx.enabled properties while the debug logging in opentelemetry agent did?

Yes exactly @laurit

mdtamim commented 2 years ago

@mdtamim Are you using the vanilla OTel javaagent? Or some vendor distribution? What version of the agent are you using?

@mateuszrzeszutek I am using vanilla OT agent which here is dependency details : groupId>io.opentelemetry.javaagent artifactId>opentelemetry-javaagent Different versions I tried are 1.11.0,1.12.0,1.13.0-SNAPSHOT

mdtamim commented 2 years ago

You could try printing out System.getenv() similarly to what you do with System.getProperties() and see whether something is set in JAVA_TOOL_OPTIONS

@laurit I printed but there are no properties set for instrumentation via env variables.

mdtamim commented 2 years ago

@mateuszrzeszutek / @trask / @laurit ,

I believe instrumentation properties are being set somehow in System properties via code in this specific issue.I checked only if some code is calling System.setProperties by enabling SecurityManager.I want to debug further for that I want to modify System class and Properties class probably adding some loggers.Is there any way I can modify rt.jar and replace these classes with custom class with additional logs?

laurit commented 2 years ago

Jdk 11 doesn't have rt.jar any more, you'll need to patch java.base module. See https://openjdk.java.net/projects/jigsaw/quick-start#xoverride Make sure you use sources from the exact same vm that you use for running and compiling. If compiler can't find something or you get a NoSuchMethodError during startup then you probably are not using the same sources. Keep in mind that java.lang.System is used very early during startup. Printing stack trace from setProperty is ok, but there are places that run so early that System.err is null. I would advise against attempting to use any fancy loggers, use System.err.println() and new Exception().printStackTrace(). Good luck.

mdtamim commented 2 years ago

Thanks @laurit I was able to modify System class in jdk.So I have got stack trace which is trying to set the instrumentation flag to false.Basically I inserted below condition in System.setproperty(String key,String value) : if (key.equals("otel.instrumentation.tomcat.enabled")) { (new Exception("trying to set key :: " + key + " with Value" + value)).printStackTrace(); }

I got exception twice once just before the startAgent() method of OpenTelemetry agent is called,below is the stacktrace :

java.lang.Exception: trying to set key :: otel.instrumentation.tomcat.enabled with Valuefalse --   | at java.base/java.lang.System.setProperty(System.java:897)   | at java.base/java.lang.ClassLoader.defineClass1(Native Method)   | at java.base/java.lang.ClassLoader.defineClass(ClassLoader.java:1017)   | at java.base/java.security.SecureClassLoader.defineClass(SecureClassLoader.java:174)   | at java.base/jdk.internal.loader.BuiltinClassLoader.defineClass(BuiltinClassLoader.java:800)   | at java.base/jdk.internal.loader.BuiltinClassLoader.findClassOnClassPathOrNull(BuiltinClassLoader.java:698)   | at java.base/jdk.internal.loader.BuiltinClassLoader.loadClassOrNull(BuiltinClassLoader.java:621)   | at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:579)   | at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:178)   | at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522)   | at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:431)   | at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:525)   | java.lang.Exception: trying to set key :: otel.instrumentation.tomcat.enabled with Valuefalse   | at java.base/java.util.Properties.setProperty(Properties.java:229)   | at java.base/java.lang.System.setProperty(System.java:906)   | at java.base/java.lang.ClassLoader.defineClass1(Native Method)   | at java.base/java.lang.ClassLoader.defineClass(ClassLoader.java:1017)   | at java.base/java.security.SecureClassLoader.defineClass(SecureClassLoader.java:174)   | at java.base/jdk.internal.loader.BuiltinClassLoader.defineClass(BuiltinClassLoader.java:800)   | at java.base/jdk.internal.loader.BuiltinClassLoader.findClassOnClassPathOrNull(BuiltinClassLoader.java:698)   | at java.base/jdk.internal.loader.BuiltinClassLoader.loadClassOrNull(BuiltinClassLoader.java:621)   | at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:579)   | at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:178)   | at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522)   | at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:431)   | at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:525)

Another exception occured in somewhere middle with below stack trace :

java.lang.Exception: trying to set key :: otel.instrumentation.tomcat.enabled with Valuefalse --   | at java.base/java.lang.System.setProperty(System.java:897)   | at java.base/java.lang.Class.forName0(Native Method)   | at java.base/java.lang.Class.forName(Class.java:398)   | at io.opentelemetry.javaagent.bootstrap.AgentClassLoader$JdkHttpServerClassLoader.loadClass(AgentClassLoader.java:453)   | at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:576)   | at io.opentelemetry.javaagent.bootstrap.AgentClassLoader.loadClass(AgentClassLoader.java:141)   | at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522)   | at io.opentelemetry.javaagent.tooling.AgentVersion.(AgentVersion.java:11)   | at io.opentelemetry.javaagent.tooling.VersionLogger.logAllVersions(VersionLogger.java:18)   | at io.opentelemetry.javaagent.tooling.AgentInstaller.logVersionInfo(AgentInstaller.java:516)   | at io.opentelemetry.javaagent.tooling.AgentInstaller.installBytebuddyAgent(AgentInstaller.java:99)   | at io.opentelemetry.javaagent.tooling.AgentStarterImpl.start(AgentStarterImpl.java:65)   | at io.opentelemetry.javaagent.bootstrap.AgentInitializer.initialize(AgentInitializer.java:35)   | at io.opentelemetry.javaagent.OpenTelemetryAgent.startAgent(OpenTelemetryAgent.java:57)   | at io.opentelemetry.javaagent.OpenTelemetryAgent.premain(OpenTelemetryAgent.java:44)   | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)   | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)   | at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)   | at java.base/java.lang.reflect.Method.invoke(Method.java:566)   | at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:513)   | at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:525)
trask commented 2 years ago

@mdtamim these are really odd callers of System.setProperty()

I noticed above that you have an env var MONITORING_TYPE=dynatrace, do you happen to have some other native agent involved in your setup that could be triggering these calls?

mdtamim commented 2 years ago

@trask looks like its due to dynatrace agent which is being internally used by application.If I disable dynatrace,the issue is going away.

mdtamim commented 2 years ago

So what should I do next? We have some 15 to 20 services in prod all using dynatrace and opentelemetry.These were working before smoothly but recently opentelemetry instumentation stopped working suddenly for only few libraries like tomcat,servlet,spring webflux...trace and span IDs are still working for internal schedular threads

trask commented 2 years ago

hi @mdtamim, running OpenTelemetry Javaagent alongside a commercial bytecode instrumenting monitoring agents is not something we officially support from the OpenTelemetry Javaagent side, because there are many potential interactions, and it's not really feasible for us to test / support these commercial tools.

Here's some additional prior discussion on this topic: https://github.com/open-telemetry/opentelemetry-java-instrumentation/issues/1534

I'd recommend reaching out to Dynatrace, I know they have OpenTelemetry support, so maybe they will have a solution for you to get the benefits of both worlds.

mdtamim commented 2 years ago

@trask thanks for your suggestion,I will check with Dynatrace team,but just wanted to know what exactly is happening behind the scene? Any idea how suddenly can stop working?I couldn't see any flag setting related code which will disable instrumentation for servers like tomcat,netty,so how it's getting set as false? I made some changes in code of open telemetry agent to explicitly set tomcat instrumentation flag to true in system properties inside opentelemetry code and it worked.Do you recommend any other alternative to make it work untill we get some permanent solution? If would be very helpful if you can throw some lights on the above questions. Thanks in advance.

trask commented 2 years ago

@mdtamim I would start with tracking down why your Dynatrace agent is setting these OpenTelemetry Javaagent settings

mdtamim commented 2 years ago

Thanks @trask .In the mean time I will check for other possible solutions

mdtamim commented 2 years ago

@trask dynatrace team confirmed that they are disabling some otel instrumentation of opentelemetry-agent in dynatrace oneagent for which oneagent provides implicit opentelemetry instrumentation.

trask commented 2 years ago

@mdtamim thanks for looping back, this is good to know!