search

elastic / apm-agent-java

https://www.elastic.co/guide/en/apm/agent/java/current/index.html
Apache License 2.0
567 stars 321 forks source link

APM agent breaks AspectJ agent #1646

Closed cdalexndr closed 3 years ago

cdalexndr commented 3 years ago

Describe the bug

Aspectj fails to load aop.xml.

Steps to reproduce

Use aspectj agent (org.aspectj:aspectjweaver:1.9.6) with apm java agent 1.20.0.

Expected behavior

In 1.10.0 it works fine.

Debug logs

Click to expand ``` 2021-02-02 01:03:09,762 [main] INFO co.elastic.apm.agent.util.JmxUtils - Found JVM-specific OperatingSystemMXBean interface: com.sun.management.OperatingSystemMXBean 2021-02-02 01:03:09,804 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - Starting Elastic APM 1.20.0 as Application on Java 11.0.8 Runtime version: 11.0.8+10-LTS VM version: 11.0.8+10-LTS (Azul Systems, Inc.) Windows 10 10.0 2021-02-02 01:03:09,805 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - VM Arguments: [-Delastic.apm.application_packages=pse, -Delastic.apm.disable_instrumentations=scheduled, -Dstagemonitor.property.overrides=stagemonitor-dev.properties, -javaagent:C:\Users\Alex\.gradle\caches\modules-2\files-2.1\org.aspectj\aspectjweaver\1.9.6\ee3b73aa16df35179255f17354d9dfd8e7822835\aspectjweaver-1.9.6.jar, -javaagent:C:\Users\Alex\.gradle\caches\modules-2\files-2.1\co.elastic.apm\elastic-apm-agent\1.20.0\cbc2e233fc22eea6ddc47d9161c09f98a5073734\elastic-apm-agent-1.20.0.jar, -agentlib:jdwp=transport=dt_socket,server=n,suspend=y,address=50642, -Xverify:none, -XX:TieredStopAtLevel=1, -Xmx2048m, -Dfile.encoding=windows-1250, -Duser.country=US, -Duser.language=en, -Duser.variant, -ea] [IndyPluginClassLoader@6c8909c3] warning parse definitions failed -- (NullPointerException) null null java.lang.NullPointerException at co.elastic.apm.agent.shaded.bytebuddy.dynamic.loading.MultipleParentClassLoader.getResources(MultipleParentClassLoader.java:129) at java.base/java.lang.ClassLoader.getResources(ClassLoader.java:1463) at co.elastic.apm.agent.shaded.bytebuddy.dynamic.loading.ByteArrayClassLoader$ChildFirst.getResources(ByteArrayClassLoader.java:1211) at org.aspectj.weaver.loadtime.DefaultWeavingContext.getResources(DefaultWeavingContext.java:51) at org.aspectj.weaver.loadtime.ClassLoaderWeavingAdaptor.parseDefinitions(ClassLoaderWeavingAdaptor.java:278) at org.aspectj.weaver.loadtime.DefaultWeavingContext.getDefinitions(DefaultWeavingContext.java:130) at org.aspectj.weaver.loadtime.ClassLoaderWeavingAdaptor.initialize(ClassLoaderWeavingAdaptor.java:173) at org.aspectj.weaver.loadtime.Aj$ExplicitlyInitializedClassLoaderWeavingAdaptor.initialize(Aj.java:337) at org.aspectj.weaver.loadtime.Aj$ExplicitlyInitializedClassLoaderWeavingAdaptor.getWeavingAdaptor(Aj.java:342) at org.aspectj.weaver.loadtime.Aj$WeaverContainer.getWeaver(Aj.java:316) at org.aspectj.weaver.loadtime.Aj.preProcess(Aj.java:108) at org.aspectj.weaver.loadtime.ClassPreProcessorAgentAdapter.transform(ClassPreProcessorAgentAdapter.java:51) at java.instrument/java.lang.instrument.ClassFileTransformer.transform(ClassFileTransformer.java:246) at java.instrument/sun.instrument.TransformerManager.transform(TransformerManager.java:188) at java.instrument/sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:563) at java.base/java.lang.ClassLoader.defineClass1(Native Method) at java.base/java.lang.ClassLoader.defineClass(ClassLoader.java:1017) at co.elastic.apm.agent.shaded.bytebuddy.dynamic.loading.ByteArrayClassLoader.access$300(ByteArrayClassLoader.java:56) at co.elastic.apm.agent.shaded.bytebuddy.dynamic.loading.ByteArrayClassLoader$ClassDefinitionAction.run(ByteArrayClassLoader.java:634) at co.elastic.apm.agent.shaded.bytebuddy.dynamic.loading.ByteArrayClassLoader$ClassDefinitionAction.run(ByteArrayClassLoader.java:586) at java.base/java.security.AccessController.doPrivileged(Native Method) at co.elastic.apm.agent.shaded.bytebuddy.dynamic.loading.ByteArrayClassLoader.findClass(ByteArrayClassLoader.java:355) at co.elastic.apm.agent.shaded.bytebuddy.dynamic.loading.ByteArrayClassLoader$ChildFirst.loadClass(ByteArrayClassLoader.java:1178) at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522) at co.elastic.apm.agent.bci.IndyBootstrap.bootstrap(IndyBootstrap.java:326) 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.base/java.lang.IndyBootstrapDispatcher.bootstrap(IndyBootstrapDispatcher.java:31) at java.base/java.lang.invoke.BootstrapMethodInvoker.invoke(BootstrapMethodInvoker.java:138) at java.base/java.lang.invoke.CallSite.makeSite(CallSite.java:307) at java.base/java.lang.invoke.MethodHandleNatives.linkCallSiteImpl(MethodHandleNatives.java:258) at java.base/java.lang.invoke.MethodHandleNatives.linkCallSite(MethodHandleNatives.java:248) at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:138) at co.elastic.apm.agent.report.ApmServerHealthChecker.checkHealthAndGetMinVersion(ApmServerHealthChecker.java:60) at co.elastic.apm.agent.report.ApmServerClient.setServerUrls(ApmServerClient.java:109) at co.elastic.apm.agent.report.ApmServerClient.start(ApmServerClient.java:104) at co.elastic.apm.agent.report.ApmServerClient.start(ApmServerClient.java:91) at co.elastic.apm.agent.impl.ElasticApmTracer.startSync(ElasticApmTracer.java:548) at co.elastic.apm.agent.impl.ElasticApmTracer.start(ElasticApmTracer.java:515) at co.elastic.apm.agent.bci.ElasticApmAgent.initialize(ElasticApmAgent.java:151) 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 co.elastic.apm.agent.bci.AgentMain.init(AgentMain.java:119) at co.elastic.apm.agent.bci.AgentMain.premain(AgentMain.java:58) 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) ```
cdalexndr commented 3 years ago

Don't have access to co.elastic.apm.agent.shaded.bytebuddy.dynamic.loading.MultipleParentClassLoader class source, but looking at debug variables, I see a possible cause:

At java.lang.ClassLoader.getResources:1463: tmp[0] = parent.getResources(name); Debug variables:

parent = {MultipleParentClassLoader@10114} 
 parents = {Arrays$ArrayList@10162}  size = 2
  0 = {ClassLoaders$AppClassLoader@9853} 
  1 = null
eyalkoren commented 3 years ago

@cdalexndr thanks for reporting and providing this valuable info! Please check this snapshot and see if it resolves the issue.

cdalexndr commented 3 years ago

@eyalkoren yes, the error is gone.

Another minor issue, there is a NullPointerException silently ignored (no log but triggers my NPE exception breakpoint) at:

getCallerClass:108, StackLocator (co.elastic.apm.agent.shaded.apache.logging.log4j.util)
getCallerClass:121, StackLocator (co.elastic.apm.agent.shaded.apache.logging.log4j.util)
getCallerClass:59, StackLocatorUtil (co.elastic.apm.agent.shaded.apache.logging.log4j.util)
getContext:44, Log4jLoggerFactory (co.elastic.apm.agent.shaded.apache.logging.slf4j)
getLogger:48, AbstractLoggerAdapter (co.elastic.apm.agent.shaded.apache.logging.log4j.spi)
getLogger:30, Log4jLoggerFactory (co.elastic.apm.agent.shaded.apache.logging.slf4j)
getLogger:358, LoggerFactory (co.elastic.apm.agent.shaded.slf4j)
getLogger:383, LoggerFactory (co.elastic.apm.agent.shaded.slf4j)
<clinit>:49, JdbcHelper (co.elastic.apm.agent.jdbc.helper)
getJdbcHelper:56, JdbcInstrumentation (co.elastic.apm.agent.jdbc)
storeSql:57, ConnectionInstrumentation (co.elastic.apm.agent.jdbc)
invokeStaticInit:-1, 2072661670 (java.lang.invoke.LambdaForm$DMH)
linkToTargetMethod:-1, 1429133319 (java.lang.invoke.LambdaForm$MH)
prepareStatement:1303, PgConnection (org.postgresql.jdbc)
prepareStatement:1735, PgConnection (org.postgresql.jdbc)
prepareStatement:436, PgConnection (org.postgresql.jdbc)
isValid:1429, PgConnection (org.postgresql.jdbc)
checkValidationSupport:458, PoolBase (com.zaxxer.hikari.pool)
checkDriverSupport:441, PoolBase (com.zaxxer.hikari.pool)
setupConnection:410, PoolBase (com.zaxxer.hikari.pool)
newConnection:363, PoolBase (com.zaxxer.hikari.pool)
newPoolEntry:206, PoolBase (com.zaxxer.hikari.pool)
createPoolEntry:477, HikariPool (com.zaxxer.hikari.pool)
checkFailFast:560, HikariPool (com.zaxxer.hikari.pool)
<init>:115, HikariPool (com.zaxxer.hikari.pool)
getConnection:112, HikariDataSource (com.zaxxer.hikari)
openConnection:56, JdbcUtils (org.flywaydb.core.internal.jdbc)
<init>:80, JdbcConnectionFactory (org.flywaydb.core.internal.jdbc)
execute:453, Flyway (org.flywaydb.core)
migrate:158, Flyway (org.flywaydb.core)
afterPropertiesSet:65, FlywayMigrationInitializer (org.springframework.boot.autoconfigure.flyway)
invokeInitMethods:1853, AbstractAutowireCapableBeanFactory (org.springframework.beans.factory.support)
initializeBean:1790, AbstractAutowireCapableBeanFactory (org.springframework.beans.factory.support)
doCreateBean:594, AbstractAutowireCapableBeanFactory (org.springframework.beans.factory.support)
createBean:516, AbstractAutowireCapableBeanFactory (org.springframework.beans.factory.support)
lambda$doGetBean$0:324, AbstractBeanFactory (org.springframework.beans.factory.support)
getObject:-1, 716207429 (org.springframework.beans.factory.support.AbstractBeanFactory$$Lambda$287)
getSingleton:226, DefaultSingletonBeanRegistry (org.springframework.beans.factory.support)
doGetBean:322, AbstractBeanFactory (org.springframework.beans.factory.support)
getBean:202, AbstractBeanFactory (org.springframework.beans.factory.support)
doGetBean:311, AbstractBeanFactory (org.springframework.beans.factory.support)
getBean:202, AbstractBeanFactory (org.springframework.beans.factory.support)
getBean:1109, AbstractApplicationContext (org.springframework.context.support)
finishBeanFactoryInitialization:869, AbstractApplicationContext (org.springframework.context.support)
refresh:551, AbstractApplicationContext (org.springframework.context.support)
refresh:143, ServletWebServerApplicationContext (org.springframework.boot.web.servlet.context)
refresh:758, SpringApplication (org.springframework.boot)
refresh:750, SpringApplication (org.springframework.boot)
refreshContext:397, SpringApplication (org.springframework.boot)
run:315, SpringApplication (org.springframework.boot)
<obsolete>:-1, Application (pse)
invoke0:-1, NativeMethodAccessorImpl (jdk.internal.reflect)
invoke:62, NativeMethodAccessorImpl (jdk.internal.reflect)
invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)
invoke:566, Method (java.lang.reflect)
run:49, RestartLauncher (org.springframework.boot.devtools.restart)

It may have no side effects, but with 1.10.0 there was no NPE.

eyalkoren commented 3 years ago

@cdalexndr thanks for reporting!

Regarding this NPE- looks like it comes from here: https://github.com/apache/logging-log4j2/blob/913e87d7747aa8d90b7bd3236c4dca2e3307336a/log4j-api/src/main/java/org/apache/logging/log4j/util/StackLocator.java#L111 You can verify that by looking for the following message in your system out log: WARNING: sun.reflect.Reflection.getCallerClass is not supported. This will impact performance. It seems it can be safely ignored. The initialization of the agent loggers will be a bit less efficient in your JVM, but you probably wouldn't notice any difference. You didn't see that in 1.10.0 because it comes from log4j, which we started using at the agent only at 1.17.0. If everything works as expected, you should be good to go with this snapshot for now and the related fix will be released with 1.21.0.

Since the reported problem seems to be fixed, I am closing this issue now, but feel free to reopen if you think there is still further handling required.