Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Agent instrumentation fails on sybase jdbc instrumentation #2644

Closed
pparapatics opened this issue Mar 26, 2021 · 12 comments · Fixed by #2756
Closed

Agent instrumentation fails on sybase jdbc instrumentation #2644

pparapatics opened this issue Mar 26, 2021 · 12 comments · Fixed by #2756
Labels
bug Something isn't working

Comments

@pparapatics
Copy link

Describe the bug

Starting from version 0.17.0 the agent instrumentation fails on a tomcat 8 application
Error message:
*** java.lang.instrument ASSERTION FAILED ***: "!errorOutstanding" with message transform method call failed at ./src/java.instrument/share/native/libinstrument/JPLISAgent.c line: 873

Versions failing: 0.17.0, 1.0.0, 1.0.1
Versions working: 0.10.1

Steps to reproduce
Start tomcat 8 with javagent

What did you expect to see?
For version 0.10.1 the application starts up, agent works as expected (propagation, exporting, ...)

What did you see instead?
Version 0.17.0 fails with message above
*** java.lang.instrument ASSERTION FAILED ***: "!errorOutstanding" with message transform method call failed at ./src/java.instrument/share/native/libinstrument/JPLISAgent.c line: 873
After that no application logs are show anymore
Tomcat does not start up correctly

What version are you using?
Versions failing: 0.17.0, 1.0.0, 1.0.1
Versions working: 0.10.1

Environment
Tomcat version: Apache Tomcat/8.5.32

Additional context
The application running in tomcat is a quite complex monolithical application.

@pparapatics pparapatics added the bug Something isn't working label Mar 26, 2021
@iNikem
Copy link
Contributor

iNikem commented Mar 26, 2021

@pparapatics What OS do you use? What version of JVM and from what vendor?

@pparapatics
Copy link
Author

pparapatics commented Mar 26, 2021 via email

@trask
Copy link
Member

trask commented Mar 26, 2021

@pparapatics can you post all the JVM command-line options you are using (including any other -javaagent flags if you have any)

also, is there a stack trace associated with the error you posted above?

@pparapatics
Copy link
Author

Sorry for the late reply.
Below you find the parameters extracted from the logs. Unfortunately there is no stack trace for the error above.
An additional remark: I tried starting tomcat without our deployable and the agent does not throw any exception.

NOTE: Picked up JDK_JAVA_OPTIONS: --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
[opentelemetry.auto.trace 2021-03-29 09:51:18:615 +0200] [main] INFO io.opentelemetry.javaagent.tooling.VersionLogger - opentelemetry-javaagent - version: 1.0.1
VersionLoggerListener.log Server version: Apache Tomcat/8.5.32
VersionLoggerListener.log Server built: Jun 20 2018 19:50:35 UTC
VersionLoggerListener.log Server number: 8.5.32.0
VersionLoggerListener.log OS Name: Linux
VersionLoggerListener.log OS Version: 5.4.0-52-generic
VersionLoggerListener.log Architecture: amd64
VersionLoggerListener.log Java Home: /home/pp/.sdkman/candidates/java/11.0.8-open
VersionLoggerListener.log JVM Version: 11.0.8+10
VersionLoggerListener.log JVM Vendor: Oracle Corporation
VersionLoggerListener.log CATALINA_BASE: /home/pp/.cache/JetBrains/IntelliJIdea2020.3/tomcat/0cb48693-4f94-4e0e-bb9e-8b844b979b84
VersionLoggerListener.log CATALINA_HOME: /opt/apache-tomcat-8.5.32
VersionLoggerListener.log Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED
VersionLoggerListener.log Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED
VersionLoggerListener.log Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=...
VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
VersionLoggerListener.log Command line argument: -Dinstallation_file=local
VersionLoggerListener.log Command line argument: -Dfile.encoding=ISO-8859-1
VersionLoggerListener.log Command line argument: -Xms2g
VersionLoggerListener.log Command line argument: -ea
VersionLoggerListener.log Command line argument: -Xverify:none
VersionLoggerListener.log Command line argument: -javaagent:/home/pp/Downloads/opentelemetry-javaagent-all-1.0.1.jar
VersionLoggerListener.log Command line argument: -Dotel.propagators=b3
VersionLoggerListener.log Command line argument: -Dotel.exporter=logging
VersionLoggerListener.log Command line argument: -Dotel.config.sampler.probability=0
VersionLoggerListener.log Command line argument: -Dcom.sun.management.jmxremote=
VersionLoggerListener.log Command line argument: -Dcom.sun.management.jmxremote.port=1099
VersionLoggerListener.log Command line argument: -Dcom.sun.management.jmxremote.ssl=false
VersionLoggerListener.log Command line argument: -Dcom.sun.management.jmxremote.password.file=/home/pp/.cache/JetBrains/IntelliJIdea2020.3/tomcat/0cb48693-4f94-4e0e-bb9e-8b844b979b84/jmxremote.password
VersionLoggerListener.log Command line argument: -Dcom.sun.management.jmxremote.access.file=/home/pp/.cache/JetBrains/IntelliJIdea2020.3/tomcat/0cb48693-4f94-4e0e-bb9e-8b844b979b84/jmxremote.access
VersionLoggerListener.log Command line argument: -Djava.rmi.server.hostname=127.0.0.1
VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
VersionLoggerListener.log Command line argument: -Dfile.encoding=ISO-8859-1
VersionLoggerListener.log Command line argument: -Xms2g
VersionLoggerListener.log Command line argument: -javaagent:/home/pp/Downloads/opentelemetry-javaagent-all-1.0.1.jar
VersionLoggerListener.log Command line argument: -Dotel.propagators=b3
VersionLoggerListener.log Command line argument: -Dotel.exporter=logging
VersionLoggerListener.log Command line argument: -Dotel.config.sampler.probability=0
VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
VersionLoggerListener.log Command line argument: -Dcatalina.base=/home/pp/.cache/JetBrains/IntelliJIdea2020.3/tomcat/0cb48693-4f94-4e0e-bb9e-8b844b979b84
VersionLoggerListener.log Command line argument: -Dcatalina.home=/opt/apache-tomcat-8.5.32
VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/opt/apache-tomcat-8.5.32/temp

@iNikem
Copy link
Contributor

iNikem commented Mar 29, 2021

I tried starting tomcat without our deployable and the agent does not throw any exception

Seems like the reason for failure is somewhere inside your application then... Can you tell us what libraries/frameworks does it use? Any chance that you can provide us with a minimal application that reproduces this failure?

@pparapatics
Copy link
Author

Yes, that makes it more difficult. There are plenty of libraries involved. Is there a possibility I can debug it on my machine to provide you more information?
e.g. include the agent source code and try to see in the debugger where it fails?

@iNikem
Copy link
Contributor

iNikem commented Mar 30, 2021

*** java.lang.instrument ASSERTION FAILED ***: "!errorOutstanding" with message transform method call failed at ./src/java.instrument/share/native/libinstrument/JPLISAgent.c line: 873

looks like JVM crash, not sure if debugging will help here... Can you try to add -Dotel.javaagent.debug=true to your command like and give us all resulting logs?

Also can you try to create a jvm crash log file and share it with us? See https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/felog001.html for explanation

@laurit
Copy link
Contributor

laurit commented Mar 30, 2021

You said that tomcat does not start up correctly. Did the jvm process crash (by crash I mean that the process has died) if so look for hs_err_pid log file in tomcat bin dir, if you can't find it then see the link that @iNikem gave and set the path where the file is generated. Usually when jvm crashes there is some info in output that describes the cash and includes the path to hs_err_pid log.
If it didn't crash, which actually seems more likely to me because *** java.lang.instrument ASSERTION FAILED ***: shouldn't be fatal, try to figure out what the process is doing, use kill -3 or jstack to dump stack traces. Examine logs to see how far in the startup your application got. Basically try to narrow down where the problem happens. As you mentioned tomcat starts when agent is enabled and application is not deployed so we can't easily reproduce the issue because it has something to do with your application. Try removing -Xverify:none from jvm arguments, -ea could also be removed, if possible also remove the jmx arguments and it looks like you have added -javaagent twice for otel agent, remove one of them and see if this changes anything.
*** java.lang.instrument ASSERTION FAILED ***: should happen when class transformation produces an exception, though it shouldn't be easy to trigger because class transformation runs inside try catch Throwable. It could happen when there is a stack overflow. Adding -verbose:class to jvm arguments and eyeballing the output might give a hint which class causes the failure (you may need to compare with -verbose:class output without agent for that). Anyway good luck, you may need it.

@pparapatics
Copy link
Author

Thank you for the debugging hints. I started the application with the debug setting on and found the following exception which relates to a stack overflow. It is related to the the jdbc instrumentation. I tried to verify that this is the root cause by deactivating the jdbc instrumenation using the flag: -Dotel.integration.jdbc.enabled=false
But it looks like this flag does not deactivate the instrumentation. Do I use the right id?

`[opentelemetry.auto.trace 2021-04-07 17:51:54:472 +0200] [localhost-startStop-1] DEBUG io.opentelemetry.javaagent.bootstrap.ExceptionLogger - Failed to handle exception in instrumentation for com.sybase.jdbc4.jdbc.SybCallableStatement on ParallelWebappClassLoader^M
context:
delegate: false^M
----------> Parent Classloader:^M
java.net.URLClassLoader@66cd621b^M

java.lang.StackOverflowError
at java.base/java.util.concurrent.ConcurrentHashMap.putIfAbsent(ConcurrentHashMap.java:1541)
at java.base/java.lang.ClassLoader.getClassLoadingLock(ClassLoader.java:668)
at java.base/jdk.internal.loader.BuiltinClassLoader.loadClassOrNull(BuiltinClassLoader.java:591)
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:576)
at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522)
at com.sybase.jdbc4.tds.Tds.rpc(Tds.java:1122)
at com.sybase.jdbc4.jdbc.SybCallableStatement.sendRpc(SybCallableStatement.java:1711)
at com.sybase.jdbc4.jdbc.SybCallableStatement.executeQuery(SybCallableStatement.java:145)
at com.sybase.jdbc4.jdbc.MdaManager.loadMetaData(MdaManager.java:486)
at com.sybase.jdbc4.jdbc.MdaManager.(MdaManager.java:188)
at com.sybase.jdbc4.jdbc.MdaManager.(MdaManager.java:171)
at com.sybase.jdbc4.jdbc.SybConnection.checkMDA(SybConnection.java:3670)
at com.sybase.jdbc4.jdbc.SybConnection.checkDBMD(SybConnection.java:3687)
at com.sybase.jdbc4.jdbc.SybConnection.getMetaData(SybConnection.java:2102)
at io.opentelemetry.javaagent.instrumentation.jdbc.JdbcTracer.extractDbInfo(JdbcTracer.java:126)
at io.opentelemetry.javaagent.instrumentation.jdbc.JdbcTracer.startSpan(JdbcTracer.java:45)
at io.opentelemetry.javaagent.instrumentation.jdbc.JdbcTracer.startSpan(JdbcTracer.java:36)
at com.sybase.jdbc4.jdbc.SybCallableStatement.executeQuery(SybCallableStatement.java:130)
at com.sybase.jdbc4.jdbc.MdaManager.loadMetaData(MdaManager.java:486)
at com.sybase.jdbc4.jdbc.MdaManager.(MdaManager.java:188)
at com.sybase.jdbc4.jdbc.MdaManager.(MdaManager.java:171)
at com.sybase.jdbc4.jdbc.SybConnection.checkMDA(SybConnection.java:3670)
at com.sybase.jdbc4.jdbc.SybConnection.checkDBMD(SybConnection.java:3687)
at com.sybase.jdbc4.jdbc.SybConnection.getMetaData(SybConnection.java:2102)
at io.opentelemetry.javaagent.instrumentation.jdbc.JdbcTracer.extractDbInfo(JdbcTracer.java:126)
at io.opentelemetry.javaagent.instrumentation.jdbc.JdbcTracer.startSpan(JdbcTracer.java:45)
at io.opentelemetry.javaagent.instrumentation.jdbc.JdbcTracer.startSpan(JdbcTracer.java:36)
at com.sybase.jdbc4.jdbc.SybCallableStatement.executeQuery(SybCallableStatement.java:130)
at com.sybase.jdbc4.jdbc.MdaManager.loadMetaData(MdaManager.java:486)
at com.sybase.jdbc4.jdbc.MdaManager.(MdaManager.java:188)
at com.sybase.jdbc4.jdbc.MdaManager.(MdaManager.java:171)
at com.sybase.jdbc4.jdbc.SybConnection.checkMDA(SybConnection.java:3670)
at com.sybase.jdbc4.jdbc.SybConnection.checkDBMD(SybConnection.java:3687)
at com.sybase.jdbc4.jdbc.SybConnection.getMetaData(SybConnection.java:2102)
at io.opentelemetry.javaagent.instrumentation.jdbc.JdbcTracer.extractDbInfo(JdbcTracer.java:126)
at io.opentelemetry.javaagent.instrumentation.jdbc.JdbcTracer.startSpan(JdbcTracer.java:45)
at io.opentelemetry.javaagent.instrumentation.jdbc.JdbcTracer.startSpan(JdbcTracer.java:36)
at com.sybase.jdbc4.jdbc.SybCallableStatement.executeQuery(SybCallableStatement.java:130)
at com.sybase.jdbc4.jdbc.MdaManager.loadMetaData(MdaManager.java:486)
at com.sybase.jdbc4.jdbc.MdaManager.(MdaManager.java:188)
at com.sybase.jdbc4.jdbc.MdaManager.(MdaManager.java:171)
at com.sybase.jdbc4.jdbc.SybConnection.checkMDA(SybConnection.java:3670)
at com.sybase.jdbc4.jdbc.SybConnection.checkDBMD(SybConnection.java:3687)
`

@mateuszrzeszutek
Copy link
Member

Try using -Dotel.instrumentation.jdbc.enabled=false

@pparapatics
Copy link
Author

Yes setting -Dotel.instrumentation.jdbc.enabled=false works.
(by the way it is stated with .integration. in the docs https://opentelemetry.io/docs/java/automatic_instrumentation/#disabled-instrumentations)

The error is gone and tracing works.
Does the stacktrace help tracing down the error?

(An additional remark. My initial description was incorrect. The error does not prevent the startup. It takes much longer and therefore it just looked like it was hanging)

@pparapatics pparapatics changed the title Agent instrumentation fails on tomcat 8 applicatoin Agent instrumentation fails on sybase jdbc instrumentation Apr 8, 2021
@iNikem
Copy link
Contributor

iNikem commented Apr 8, 2021

Does the stacktrace help tracing down the error?

Yes, I believe this gives a very good indication to the source of this error.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
5 participants