Application deployed in tomcat server stops working when java agent is attached to it

Bhavani_Ananth · May 11, 2021, 8:07am

Thanks in advance for all your help!
These are the details for your reference
Kibana version: 7.12.1
Elasticsearch version: 7.12.1
APM Server version: 7.12.1
APM Agent language and version: java, 1.23
'When we try to add the java agent to tomcat server, the application does not start.'

Server version: Apache Tomcat/7.0.106
Server built: Sep 16 2020 08:33:41 UTC
Server number: 7.0.106.0
OS Name: Linux
OS Version: 4.14.35-2047.502.4.1.el7uek.x86_64
Architecture: amd64
JVM Version: 1.7.0_301-b09
JVM Vendor: Oracle Corporation

Steps to reproduce:

Attached java agent 1.23 to the setenv.sh of tomcat.
Tomcat starts but the application throws exceptions and does not start
We also tried the suggestions mentioned in the Troubleshooting guide - part of uncommon problems
4 tried adding -XX:CompileCommand=exclude,java.lang.invoke.LambdaForm*::* to JAVA_OPTS
tried adding -Delastic.apm.delay_agent_premain_ms=10000 to CATALINA_OPTS
6 The VerifyError and error related to invokedDynamics are repeated many times.

Refer the log snippet below

Delaying Elastic APM Agent initialization by 3000 milliseconds.
co.elastic.apm.agent.configuration.StartupInfo - Starting Elastic APM 1.23.0 as Stage-mis on Java 1.7.0
2021-05-10 07:15:20,030 [elastic-apm-agent-initialization] INFO  co.elastic.apm.agent.configuration.StartupInfo - global_labels: 'env= Stage' (source: Java System Prope
rties)
2021-05-10 07:15:20,030 [elastic-apm-agent-initialization] INFO  co.elastic.apm.agent.configuration.StartupInfo - server_url: 'http://xx.xx.xx.xx:8200' (source: Java Sy
stem Properties)
2021-05-10 07:15:20,031 [elastic-apm-agent-initialization] INFO  co.elastic.apm.agent.configuration.StartupInfo - application_packages: 'org,com' (source: Java System Properties)
2021-05-10 07:15:21,517 [elastic-apm-agent-initialization] WARN  co.elastic.apm.agent.bci.ElasticApmAgent - Error while redefining classes Error invoking java.lang.instrument.Instrumentation#retransformClasses
2021-05-10 07:15:21,522 [elastic-apm-tracer-initializer] INFO  co.elastic.apm.agent.impl.ElasticApmTracer - Delaying initialization of tracer for 5000ms
May 10, 2021 7:15:26 AM org.apache.catalina.mbeans.GlobalResourcesLifecycleListener createMBeans
SEVERE: Exception processing Global JNDI Resources
javax.naming.NamingException: Could not create resource factory instance [Root exception is java.lang.VerifyError: (class: ch/qos/logback/classic/Logger, method: error
signature: (Ljava/lang/String;Ljava/lang/Throwable;)V) invokedynamic bytecode is not supported in this class file version]
        at org.apache.naming.factory.FactoryBase.getObjectInstance(FactoryBase.java:86)
        at javax.naming.spi.NamingManager.getObjectInstance(NamingManager.java:331)
        at org.apache.naming.NamingContext.lookup(NamingContext.java:847)
        at org.apache.naming.NamingContext.lookup(NamingContext.java:159)
        at org.apache.naming.NamingContextBindingsEnumeration.nextElementInternal(NamingContextBindingsEnumeration.java:117)
        at org.apache.naming.NamingContextBindingsEnumeration.next(NamingContextBindingsEnumeration.java:71)
        at org.apache.naming.NamingContextBindingsEnumeration.next(NamingContextBindingsEnumeration.java:34)
        at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.createMBeans(GlobalResourcesLifecycleListener.java:138)
        at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.createMBeans(GlobalResourcesLifecycleListener.java:145)
        at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.createMBeans(GlobalResourcesLifecycleListener.java:110)
        at .......
Caused by: java.lang.VerifyError: (class: ch/qos/logback/classic/Logger, method: error signature: (Ljava/lang/String;Ljava/lang/Throwable;)V) invokedynamic bytecode is
not supported in this class file version
        at ch.qos.logback.classic.LoggerContext.<init>(LoggerContext.java:79)
        at org.slf4j.impl.StaticLoggerBinder.<init>(StaticLoggerBinder.java:59)
        at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:50)
        at org.slf4j.LoggerFactory.bind(LoggerFactory.java:128)
        at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:108)
        at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:279)
        at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:252)
        at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:265)
        at org.apache.activemq.jndi.JNDIReferenceFactory.<clinit>(JNDIReferenceFactory.java:39)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
        at org.apache.naming.factory.FactoryBase.getObjectInstance(FactoryBase.java:75)
        ... 22 more

May 10, 2021 7:15:26 AM org.apache.catalina.core.StandardService startInternal
INFO: Starting service [Catalina]
May 10, 2021 7:15:26 AM org.apache.catalina.core.StandardEngine startInternal
INFO: Starting Servlet Engine: Apache Tomcat/7.0.106
May 10, 2021 7:15:26 AM org.apache.catalina.startup.HostConfig deployDescriptor
INFO: Deploying deployment descriptor [/base/path//conf/Catalina/localhost/logs.xml]
2021-05-10 07:15:26,523 [elastic-apm-tracer-initializer] INFO  co.elastic.apm.agent.impl.ElasticApmTracer - end wait
2021-05-10 07:15:26,542 [elastic-apm-tracer-initializer] INFO  co.elastic.apm.agent.impl.ElasticApmTracer - Tracer switched to RUNNING state
2021-05-10 07:15:26,550 [elastic-apm-server-healthcheck] INFO  co.elastic.apm.agent.report.ApmServerHealthChecker - Elastic APM server is available: {  "build_date": "2
021-04-20T19:55:39Z",  "build_sha": "32f34ed4298d648bf9476790f2a8a54d72805bb6",  "version": "7.12.1"}
May 10, 2021 7:15:29 AM org.apache.catalina.core.ContainerBase addChildInternal
SEVERE: ContainerBase.addChild: start:
org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost].StandardContext[/logs]]
        at org.apache.catalina.util.LifecycleBase.handleSubClassException(LifecycleBase.java:440)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:198)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:1007)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:983)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:639)
        at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:712)
        at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:2001)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.VerifyError: (class: javax/servlet/GenericServlet, method: init signature: (Ljavax/servlet/ServletConfig;)V) invokedynamic bytecode is not supporte
d in this class file version
        at java.lang.Class.getDeclaredFields0(Native Method)
        at java.lang.Class.privateGetDeclaredFields(Class.java:2509)
        at java.lang.Class.getDeclaredFields(Class.java:1819)
        at org.apache.catalina.util.Introspection.getDeclaredFields(Introspection.java:106)
        at org.apache.catalina.startup.WebAnnotationSet.loadFieldsAnnotation(WebAnnotationSet.java:270)
        at org.apache.catalina.startup.WebAnnotationSet.loadApplicationServletAnnotations(WebAnnotationSet.java:138)
        at org.apache.catalina.startup.WebAnnotationSet.loadApplicationAnnotations(WebAnnotationSet.java:70)
        at org.apache.catalina.startup.ContextConfig.applicationAnnotationsConfig(ContextConfig.java:417)
        at org.apache.catalina.startup.ContextConfig.configureStart(ContextConfig.java:891)
        at org.apache.catalina.startup.ContextConfig.lifecycleEvent(ContextConfig.java:388)
        at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5536)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        ... 10 more

May 10, 2021 9:52:50 AM org.apache.catalina.core.ContainerBase addChildInternal
SEVERE: ContainerBase.addChild: start:
org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost].StandardContext[/mis-all-1.0.0]]
        at org.apache.catalina.util.LifecycleBase.handleSubClassException(LifecycleBase.java:440)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:198)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:1007)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:983)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:639)
        at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1296)
        at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:2037)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.VerifyError: (class: javax/servlet/GenericServlet, method: init signature: (Ljavax/servlet/ServletConfig;)V) invokedynamic bytecode is not supported in this class file version
        at java.lang.Class.getDeclaredFields0(Native Method)
        at java.lang.Class.privateGetDeclaredFields(Class.java:2509)
        at java.lang.Class.getDeclaredFields(Class.java:1819)
        at org.apache.catalina.util.Introspection.getDeclaredFields(Introspection.java:106)
        at org.apache.catalina.startup.WebAnnotationSet.loadFieldsAnnotation(WebAnnotationSet.java:270)
        at org.apache.catalina.startup.WebAnnotationSet.loadApplicationServletAnnotations(WebAnnotationSet.java:138)
        at org.apache.catalina.startup.WebAnnotationSet.loadApplicationAnnotations(WebAnnotationSet.java:70)
        at org.apache.catalina.startup.ContextConfig.applicationAnnotationsConfig(ContextConfig.java:417)
        at org.apache.catalina.startup.ContextConfig.configureStart(ContextConfig.java:891)
        at org.apache.catalina.startup.ContextConfig.lifecycleEvent(ContextConfig.java:388)
        at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5536)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        ... 10 more
.......
May 10, 2021 9:52:50 AM org.apache.catalina.startup.HostConfig deployDirectory
SEVERE: Error deploying web application directory [/path/of/web/application]
java.lang.IllegalStateException: ContainerBase.addChild: start: org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost].StandardContext[/mis-all-1.0.0]]
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:1011)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:983)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:639)
        at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1296)
        at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:2037)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
        at java.lang.Thread.run(Thread.java:745)
...........

Sylvain_Juge · May 11, 2021, 12:02pm

Hi @Bhavani_Ananth , it seems that you are facing a bytecode instrumentation issue, from the following log output we know that some classes in Logback can't be properly instrumented.

You also seem to be using the latest Java 7 JDK available from Oracle (update 301) Java SE 7 Advanced
Because this version is not publicly available we can't directly try to reproduce the issue you are facing.

However, the issue is a bit unexpected here as:

instrumentation works with earlier Java 7 versions (7u80 and later) and we had no such reports so far
the JVM reports that invokedynamic bytecode is not supported, which means the JVM supports invokedynamic bytecode we are using for instrumentation.

The issue happens with Logback and also some servlet classes, thus it's not really specific to Logback.

Does the issue also happens when you remove application_packages ? You are using a very broad value here.
Can you provide the agent log file with log_level=debug (make sure to remove any sensitive values)
can you provide your JVM parameters (output of jps -lv should be enough, and make sure to remove any sensitive value too).

Bhavani_Ananth · May 17, 2021, 7:35am

Thaks Sylvain for your prompt response.

Does the issue also happens when you remove application_packages ? You are using a very broad value here. : Yes , it happens even when we give specific packages.
can you provide your JVM parameters (output of jps -lv should be enough, and make sure to remove any sensitive value too).: Refer the snippet below
'''
5402 org.apache.catalina.startup.Bootstrap -Djava.util.logging.config.file=/app/none/tomcat/tomcat_none/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Dfile.encoding=UTF-8 -DdbDialect=org.hibernate.dialect.Oracle10gDialect -DshowSql=false -XX:-UseSplitVerifier -Xms4g -Xmx10g -XX:NewSize=1600m -XX:MaxNewSize=1600m -XX:PermSize=512m -XX:MaxPermSize=512m -XX:ThreadStackSize=256k -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+UseTLAB -XX:+CMSIncrementalMode -XX:+CMSIncrementalPacing -XX:CMSIncrementalDutyCycleMin=0 -XX:CMSIncrementalDutyCycle=10 -XX:MaxTenuringThreshold=16 -XX:SurvivorRatio=16 -XX:CMSInitiatingOccupancyFraction=65 -XX:+AggressiveOpts -Djava.awt.headless=true -XX:+DisableExplicitGC -XX:+UseBiasedLocking -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:MinHeapFreeRatio=10 -XX:MaxHeapFreeRatio=20 -XX:+PrintHeapAtGC -XX:-TraceClassUnloading -XX:-CMSClassUnloadingEnabled -XX:+CMSClassUnloadingEnabled -XX:+HeapDumpOnOutOfMemoryError -DcacheEnabled=true -DserviceCon

5799 org.apache.catalina.startup.Bootstrap -Djava.util.logging.config.file=/app/none/tomcat/tomcat_none/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Dfile.encoding=UTF-8 -DdbDialect=org.hibernate.dialect.Oracle10gDialect -DshowSql=false -XX:-UseSplitVerifier -Xms2g -Xmx6g -XX:NewSize=1600m -XX:MaxNewSize=1600m -XX:PermSize=512m -XX:MaxPermSize=512m -XX:ThreadStackSize=256k -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+UseTLAB -XX:+CMSIncrementalMode -XX:+CMSIncrementalPacing -XX:CMSIncrementalDutyCycleMin=0 -XX:CMSIncrementalDutyCycle=10 -XX:MaxTenuringThreshold=16 -XX:SurvivorRatio=16 -XX:CMSInitiatingOccupancyFraction=65 -XX:+AggressiveOpts -Djava.awt.headless=true -XX:+DisableExplicitGC -XX:+UseBiasedLocking -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:MinHeapFreeRatio=10 -XX:MaxHeapFreeRatio=20 -XX:+PrintHeapAtGC -XX:-TraceClassUnloading -XX:-CMSClassUnloadingEnabled -XX:+CMSClassUnloadingEnabled -XX:+HeapDumpOnOutOfMemoryError -DcacheEnabled=true -DserviceCon

5346 org.apache.catalina.startup.Bootstrap -Djava.util.logging.config.file=/app/none/tomcat/tomcat_none/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Dfile.encoding=UTF-8 -DdbDialect=org.hibernate.dialect.Oracle10gDialect -DshowSql=false -XX:-UseSplitVerifier -Xms4g -Xmx10g -XX:NewSize=1600m -XX:MaxNewSize=1600m -XX:PermSize=512m -XX:MaxPermSize=512m -XX:ThreadStackSize=256k -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+UseTLAB -XX:+CMSIncrementalMode -XX:+CMSIncrementalPacing -XX:CMSIncrementalDutyCycleMin=0 -XX:CMSIncrementalDutyCycle=10 -XX:MaxTenuringThreshold=16 -XX:SurvivorRatio=16 -XX:CMSInitiatingOccupancyFraction=65 -XX:+AggressiveOpts -Djava.awt.headless=true -XX:+DisableExplicitGC -XX:+UseBiasedLocking -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:MinHeapFreeRatio=10 -XX:MaxHeapFreeRatio=20 -XX:+PrintHeapAtGC -XX:-TraceClassUnloading -XX:-CMSClassUnloadingEnabled -XX:+CMSClassUnloadingEnabled -XX:+HeapDumpOnOutOfMemoryError -DcacheEnabled=true -DserviceConsum
'''

Sylvain_Juge · May 18, 2021, 9:48am

Hi @Bhavani_Ananth ,

Could you try to configure disable_instrumentations=experimental,logback-ecs,logging
(doc) and report if that makes a difference here ?

Also, which version of logback-classic are you using here ?

Bhavani_Ananth · May 20, 2021, 7:10am

Thanks Sylvain,

The logback classic version used is - 1.0.6

Even after configuring disable_instrumentations=experimental,logback-ecs,logging, the following error is thrown
'''
SEVERE: ContainerBase.addChild: start:
org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost].StandardContext[/mis-all-1.0.0]]
at org.apache.catalina.util.LifecycleBase.handleSubClassException(LifecycleBase.java:440)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:198)
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:1007)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:983)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:639)
at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1296)
at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:2037)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.VerifyError: (class: javax/servlet/GenericServlet, method: init signature: (Ljavax/servlet/ServletConfig;)V) invokedynamic bytecode is not supported in this class file version
at java.lang.Class.getDeclaredFields0(Native Method)
at java.lang.Class.privateGetDeclaredFields(Class.java:2509)
at java.lang.Class.getDeclaredFields(Class.java:1819)
at org.apache.catalina.util.Introspection.getDeclaredFields(Introspection.java:106)
at org.apache.catalina.startup.WebAnnotationSet.loadFieldsAnnotation(WebAnnotationSet.java:270)
at org.apache.catalina.startup.WebAnnotationSet.loadApplicationServletAnnotations(WebAnnotationSet.java:138)
at org.apache.catalina.startup.WebAnnotationSet.loadApplicationAnnotations(WebAnnotationSet.java:70)
at org.apache.catalina.startup.ContextConfig.applicationAnnotationsConfig(ContextConfig.java:417)
at org.apache.catalina.startup.ContextConfig.configureStart(ContextConfig.java:891)
at org.apache.catalina.startup.ContextConfig.lifecycleEvent(ContextConfig.java:388)
at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5536)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
... 10 more

May 20, 2021 5:48:15 AM org.apache.catalina.startup.HostConfig deployDirectory
SEVERE: Error deploying web application directory [/aaa/bbb/cc/ddd/webapps/xx-1.0.0]
java.lang.IllegalStateException: ContainerBase.addChild: start: org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost].StandardContext[/mis-all-1.0.0]]
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:1011)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:983)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:639)
at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1296)
at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:2037)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
at java.lang.Thread.run(Thread.java:745)
'''

system · June 10, 2021, 3:10am

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