ElasticSearch Java Agent for tomcat stops my application from running

souravtyson · November 20, 2018, 2:16pm

Hi Team,

I have been trying to configure APM for tomcat. I added following configuration in setenv.sh file :

export CATALINA_OPTS="$CATALINA_OPTS -javaagent:/home/webtech/elastic-apm-agent-1.0.1.jar"
export CATALINA_OPTS="$CATALINA_OPTS -Delastic.apm.service_name=ServiceController"
export CATALINA_OPTS="$CATALINA_OPTS -Delastic.apm.application_packages=com.product"
export CATALINA_OPTS="$CATALINA_OPTS -Delastic.apm.server_urls=http://:8300"

My APM server is up and running. I can see on kibana that i am able to connect to apm server. But when i tried to run the tomcat i found that my application which is deployed on tomcat is not running, i cannot access my application, only tomcat process is up.

So i went through the tomcat catalina.out file and i found these logging in it :

2018-11-20 12:42:27.965 [apm-reporter] INFO co.elastic.apm.report.IntakeV2ReportingEventHandler - Backing off for 36 seconds (±10%)

INFO: Illegal access: this web application instance has been stopped already. Could not load com.google.common.base.MoreObjects$ToStringHelper. The eventual following stack trace is caused by an error thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access, and has no functional impact.

java.lang.IllegalStateException
at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1564)
at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1523)
at com.google.common.base.MoreObjects.toStringHelper(MoreObjects.java:95)
at com.google.common.cache.CacheStats.toString(CacheStats.java:268)
at com.company.util.cache.provider.GuavaCacheProvider$2.run(GuavaCacheProvider.java:177)
at java.util.TimerThread.mainLoop(Timer.java:555)
at java.util.TimerThread.run(Timer.java:505)

Note : If i remove the APM configuration from setenv.sh file my application is accessible and i could not
find any of the above error.

Thanks
Sourav

souravtyson · November 21, 2018, 9:43am

Now their is another finding. I thought that their might be some issue with my tomcat version which was 7.x. So, i tried with another product which uses tomcat 8.5, even then the APM monitoring does work.
Please help me where am i doing the mistake.
This time i get following error:

21-Nov-2018 08:26:46.336 SEVERE [localhost-startStop-1] org.apache.catalina.startup.ContextConfig.processAnnotationsJar Unable to process Jar entry [META-INF/versions/9/module-info.class] from Jar [file:/home/webtech/elastic-apm-agent-1.0.1.jar] for annotations
 org.apache.tomcat.util.bcel.classfile.ClassFormatException: Invalid byte tag in constant pool: 19
        at org.apache.tomcat.util.bcel.classfile.Constant.readConstant(Constant.java:97)
        at org.apache.tomcat.util.bcel.classfile.ConstantPool.<init>(ConstantPool.java:54)
        at org.apache.tomcat.util.bcel.classfile.ClassParser.readConstantPool(ClassParser.java:174)
        at org.apache.tomcat.util.bcel.classfile.ClassParser.parse(ClassParser.java:83)
        at org.apache.catalina.startup.ContextConfig.processAnnotationsStream(ContextConfig.java:2053)
        at org.apache.catalina.startup.ContextConfig.processAnnotationsJar(ContextConfig.java:2000)
        at org.apache.catalina.startup.ContextConfig.processAnnotationsUrl(ContextConfig.java:1970)
        at org.apache.catalina.startup.ContextConfig.processAnnotations(ContextConfig.java:1923)
        at org.apache.catalina.startup.ContextConfig.webConfig(ContextConfig.java:1163)
        at org.apache.catalina.startup.ContextConfig.configureStart(ContextConfig.java:775)
        at org.apache.catalina.startup.ContextConfig.lifecycleEvent(ContextConfig.java:299)
        at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:94)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5087)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:752)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:728)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:734)
        at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1107)
        at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:1841)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

Eyal_Koren · November 21, 2018, 2:05pm

Hi Sourav,

Sorry to hear you are having troubles installing the agent.
Which JVM are you using?

Thanks,
Eyal.

souravtyson · November 21, 2018, 2:07pm

Hi,

Thanks for the reply. I am using jdk1.8.0_111 and tomcat : apache-tomcat-8.5.8

Thanks,
Sourav Suman

Eyal_Koren · November 21, 2018, 3:07pm

Sourav,

The second error doesn't seem to be specific to the agent, but a problem with the Tomcat's embedded BCEL. It may be caused by introducing agent classes though containing bytecode that BCEL fails to parse. The solution I see when searching for that is upgrading your Tomcat to 8.5.12 or higher

As for the first error- 2018-11-20 12:42:27.965 [apm-reporter] INFO co.elastic.apm.report.IntakeV2ReportingEventHandler - Backing off for 36 seconds (±10%) indicates that the agent cannot connect to the APM server, so it backs off. This, however can't explain the problem you see. What are the Tomcat and Java versions in this case?

Thanks,
Eyal.

souravtyson · November 21, 2018, 3:14pm

Hi,

For the first issue my env details is :

tomcat - apache-tomcat-7.0.22
java - jdk1.8.0_101

For the second issue i referred this link. So i thought the tomcat 8.5.8 will work. Any possibility that i can do it without upgrading my tomcat.

And regarding the agent not being able to connect to APM server, my APM server shows me the status that it is running and i can easily telnet from my agent server to APM server and currently i am successfully pushing the tomcat log to elastic(APM Server).

Regards,
Sourav Suman

Eyal_Koren · November 22, 2018, 4:13am

Hi,

You are right- you are absolutely within the supported matrix we stated, the Tomcat 8.5.8 thing is something we need to further check. However, even if we reproduce it, we are likely to decide not to dig in to see what exact annotation is causing that and change our code just to support specific version with a known issue. But we should update the documented supported matrix at least.

I am not sure whether the problem with the tomcat 7 was the same one (although many cases I found online for the BCEL problem were about the combination of tomcat 7 with jdk 8). If you want to go back to this one, try to look further into the logs, as I couldn't find anything I can rely on.

And lastly- what I said about 2018-11-20 12:42:27.965 [apm-reporter] INFO co.elastic.apm.report.IntakeV2ReportingEventHandler - Backing off for 36 seconds (±10%) is that there was a temporary problem with agent communicating the server, maybe even because you started the server after the agent. Which APM server version are you using BTW?

Thanks,
Eyal.

Eyal_Koren · November 22, 2018, 4:29am

Sourav,

I opened this issue: https://github.com/elastic/apm-agent-java/issues/337.
If you DO upgrade your tomcat before we get to it and have some more info that you would like to share- that will be great.

Thanks,
Eyal.

souravtyson · November 22, 2018, 7:09am

Eyal

That would be really good if you update the document. So that one can verify before using the APM module.

I have apm-server-6.5.0-x86_64.rpm package for APM server.

What kind of information do you need from my side?

By the way i wanted to know how you are using the byte code injection in java. Is their any documentation which i can follow.

Thanks,
Sourav

Eyal_Koren · November 22, 2018, 8:33am

Sourav,

APM server version is valid. I assume what we saw in log was just temporary failure of communication (maybe server was not up yet).

If you can find some more info in the logs about the first issue you reported at the top of this topic - that may help, we didn't see an error there.

For instrumentation we use ByteBuddy, which relies on ASM. You can see everything in github.

Regards,
Eyal.

souravtyson · November 22, 2018, 8:41am

Eyal,

Here are some other logs i think you can find useful :

Exception in thread "com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0" java.lang.VerifyError: (class: com/mchange/v2/c3p0/impl/NewProxyStatement, method: execute signature: (Ljava/lang/String;)Z) Illegal type in constant pool
        at com.mchange.v2.c3p0.impl.NewProxyConnection.createStatement(NewProxyConnection.java:97)
        at com.mchange.v2.c3p0.impl.DefaultConnectionTester.activeCheckConnection(DefaultConnectionTester.java:138)
        at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1.testPooledConnection(C3P0PooledConnectionPool.java:184)
        at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1.refurbishResourceOnCheckin(C3P0PooledConnectionPool.java:138)
        at com.mchange.v2.resourcepool.BasicResourcePool.attemptRefurbishResourceOnCheckin(BasicResourcePool.java:1132)
        at com.mchange.v2.resourcepool.BasicResourcePool.access$100(BasicResourcePool.java:32)
        at com.mchange.v2.resourcepool.BasicResourcePool$6.run(BasicResourcePool.java:862)
        at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:368)

SEVERE: The web application [/dummy] appears to have started a thread named [AsyncAppender-Dispatcher-Thread-9] but has failed to stop it. This is very likely to create a memory leak.

Thanks
Sourav

Eyal_Koren · November 22, 2018, 9:04am

Sourav,

This may be useful indeed. Looks like our instrumentation of this c3p0 Statement results in invalid bytecode.
Can you tell the exact version of the c3p0 library you are using and which Java version it was compiled with?

Thanks,
Eyal.

souravtyson · November 22, 2018, 10:22am

Eyal,

c3p0 - c3p0-0.9.0.4.jar
java - java 8(not sure, if you know the way to find the java version used to compile jar, let me know)

Thanks
Sourav

Eyal_Koren · November 22, 2018, 11:24am

Sourav,

From what I see it seems very old, maybe even compiled with Java 1.4?
We should release a bugfix soon that addresses libs compiled with Java older than 5 (not instrumenting them...).
If indeed this is the problem, and the c3p0 wraps a supported JDBC driver - this may work out, so you may want to try it out.

Regards,
Eyal.

souravtyson · November 22, 2018, 11:26am

Eyal,

Are you suggesting to upgrade my c3p0 drivers?

Thanks
Sourav

Eyal_Koren · November 22, 2018, 11:29am

No, upgrade to our next bugfix release and see if it solves the problem

souravtyson · November 22, 2018, 11:31am

When can i get the new build with bug fixes?

Eyal_Koren · November 22, 2018, 11:32am

Hopefully next week (v1.0.2)

system · December 13, 2018, 7:32am

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.