search

elastic / apm-agent-java

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

enable_instrumentation not working for plugins #3428

Closed Shaoranlaos closed 11 months ago

Shaoranlaos commented 11 months ago

Describe the bug

If only specifc instrumentations are activated via enable_instrumentation, the loaded own plugins (via elastic.apm.plugins_dir) are no longer working.

The only problem i found in the Log is the line "2023-11-14 13:23:38,623 [main] WARN co.elastic.apm.agent.bci.bytebuddy.InstallationListenerImpl - Byte Buddy warmup ended without transforming at least one class. The agent may not work as expected." which seems to indicate something is not active if enable_instrumentation is used.

Steps to reproduce

  1. Load a plugin via elastic.apm.plugins_dir
  2. Only enable the instrumentation of this plugin via "enable_instrumentation"
  3. Try to generate a transaction via the instrumentation of the plugin
  4. Check Kiabana APM -> no Transaction received

Expected behavior

Application should be fully instrumented via the plugin and send transaction against APM Server.

Debug logs

Click to expand 2023-11-14 13:23:37,509 [main] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-configuration-reloader` was created. The original context class loader of this thread (sun.misc.Launcher$AppClassLoader@18b4aac2) has been overridden 2023-11-14 13:23:37,568 [main] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-metadata-0` was created. The original context class loader of this thread (sun.misc.Launcher$AppClassLoader@18b4aac2) has been overridden 2023-11-14 13:23:37,569 [main] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-metadata-1` was created. The original context class loader of this thread (sun.misc.Launcher$AppClassLoader@18b4aac2) has been overridden 2023-11-14 13:23:37,573 [elastic-apm-metadata-1] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-cloud-metadata-0` was created. The original context class loader of this thread (ShadedClassLoader{parent=ShadedClassLoader{parent=null, customPrefix='cached-lookup-key/', manifest=java.util.jar.Manifest@703e9f79, jarUrl=file:/C:/Users/xxx/.m2/repository/co/elastic/apm/elastic-apm-agent/1.42.0/elastic-apm-agent-1.42.0.jar}, customPrefix='agent/', manifest=java.util.jar.Manifest@703e9f79, jarUrl=file:/C:/Users/xxx/.m2/repository/co/elastic/apm/elastic-apm-agent/1.42.0/elastic-apm-agent-1.42.0.jar}) has been overridden 2023-11-14 13:23:37,575 [elastic-apm-metadata-1] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-cloud-metadata-1` was created. The original context class loader of this thread (ShadedClassLoader{parent=ShadedClassLoader{parent=null, customPrefix='cached-lookup-key/', manifest=java.util.jar.Manifest@703e9f79, jarUrl=file:/C:/Users/xxx/.m2/repository/co/elastic/apm/elastic-apm-agent/1.42.0/elastic-apm-agent-1.42.0.jar}, customPrefix='agent/', manifest=java.util.jar.Manifest@703e9f79, jarUrl=file:/C:/Users/xxx/.m2/repository/co/elastic/apm/elastic-apm-agent/1.42.0/elastic-apm-agent-1.42.0.jar}) has been overridden 2023-11-14 13:23:37,576 [elastic-apm-cloud-metadata-0] DEBUG co.elastic.apm.agent.util.UrlConnectionUtils - Opening http://169.254.169.254/latest/api/token without proxy 2023-11-14 13:23:37,635 [elastic-apm-metadata-1] DEBUG co.elastic.apm.agent.util.UrlConnectionUtils - Opening http://169.254.169.254/metadata/instance/compute?api-version=2019-08-15 without proxy 2023-11-14 13:23:37,635 [elastic-apm-cloud-metadata-1] DEBUG co.elastic.apm.agent.util.UrlConnectionUtils - Opening http://metadata.google.internal/computeMetadata/v1/?recursive=true without proxy 2023-11-14 13:23:37,640 [elastic-apm-cloud-metadata-0] DEBUG co.elastic.apm.agent.util.UrlConnectionUtils - Opening http://169.254.169.254/latest/dynamic/instance-identity/document without proxy 2023-11-14 13:23:37,651 [elastic-apm-metadata-1] DEBUG co.elastic.apm.agent.impl.metadata.CloudMetadataProvider - cloud_provider configured AUTO, no cloud metadata discovered 2023-11-14 13:23:37,700 [main] INFO co.elastic.apm.agent.util.JmxUtils - Found JVM-specific OperatingSystemMXBean interface: com.sun.management.OperatingSystemMXBean 2023-11-14 13:23:37,702 [main] DEBUG co.elastic.apm.agent.metrics.builtin.CGroupMetrics - Cannot find/read /proc/self/cgroup file. Cgroup metrics will not be reported. 2023-11-14 13:23:37,709 [main] INFO co.elastic.apm.agent.util.JmxUtils - Found JVM-specific ThreadMXBean interface: com.sun.management.ThreadMXBean 2023-11-14 13:23:37,737 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - Starting Elastic APM 1.42.0 as HTTP-Gateway on Java 1.8.0_282 Runtime version: 1.8.0_282-b08 VM version: 25.282-b08 (AdoptOpenJDK) Windows 10 10.0 2023-11-14 13:23:37,737 [main] DEBUG co.elastic.apm.agent.configuration.StartupInfo - VM Arguments: [-Dxxx.propertypath=./cfg/HTTP-Gateway, -Dxxx.applicationname=HTTP-Gateway, -Dinstance=1, -Dhttp-inbound-port=9199, -javaagent:xxx\ElasticStack\apm\elastic-apm-agent-1.42.0.jar, -Delastic.apm.server_urls=http://xxxx:8200,http://xxxx:8200, -Delastic.apm.service_name=HTTP-Gateway, -Delastic.apm.plugins_dir=xxx\ElasticStack\apm\apm-plugins, -Delastic.apm.application_packages=com.xxx, -Delastic.apm.log_level=DEBUG, -Delastic.apm.enable_instrumentations=tibcorv, -Delastic.apm.environment=development, -Delastic.apm.log_file=elastic-apm.log, -Dfile.encoding=UTF-8, -Dstdout.encoding=UTF-8, -Dstderr.encoding=UTF-8] 2023-11-14 13:23:37,738 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - service_name: 'HTTP-Gateway' (source: Java System Properties) 2023-11-14 13:23:37,738 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - environment: 'development' (source: Java System Properties) 2023-11-14 13:23:37,738 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - enable_instrumentations: 'tibcorv' (source: Java System Properties) 2023-11-14 13:23:37,738 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - plugins_dir: 'xxx\ElasticStack\apm\apm-plugins' (source: Java System Properties) 2023-11-14 13:23:37,738 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - server_urls: 'http://xxxx:8200,http://xxxx:8200' (source: Java System Properties) 2023-11-14 13:23:37,738 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - application_packages: 'com.xxx' (source: Java System Properties) 2023-11-14 13:23:37,738 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - log_level: 'DEBUG' (source: Java System Properties) 2023-11-14 13:23:37,739 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - log_file: 'elastic-apm.log' (source: Java System Properties) 2023-11-14 13:23:37,741 [main] INFO co.elastic.apm.agent.bci.ElasticApmAgent - Loading plugin eclipse-milo-apm-plugin-1.0.0-jar-with-dependencies.jar 2023-11-14 13:23:37,857 [main] INFO co.elastic.apm.agent.bci.ElasticApmAgent - Loading plugin tibco-apm-plugin-1.4.1-SNAPSHOT-jar-with-dependencies.jar 2023-11-14 13:23:38,011 [main] DEBUG co.elastic.apm.agent.util.DependencyInjectingServiceLoader - Skipping co.elastic.apm.agent.httpclient.HttpClientInstrumentation because it only applies to more recent Java versions and the JVM running this app is too old to load it 2023-11-14 13:23:38,012 [main] DEBUG co.elastic.apm.agent.util.DependencyInjectingServiceLoader - Skipping co.elastic.apm.agent.httpclient.HttpClientAsyncInstrumentation because it only applies to more recent Java versions and the JVM running this app is too old to load it 2023-11-14 13:23:38,012 [main] DEBUG co.elastic.apm.agent.util.DependencyInjectingServiceLoader - Skipping co.elastic.apm.agent.httpclient.HttpRequestHeadersInstrumentation because it only applies to more recent Java versions and the JVM running this app is too old to load it 2023-11-14 13:23:38,386 [main] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-type-cache-pool-cleaner` was created. The original context class loader of this thread (sun.misc.Launcher$AppClassLoader@18b4aac2) has been overridden 2023-11-14 13:23:38,393 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.bbwarmup.WarmupInstrumentation 2023-11-14 13:23:38,393 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.httpclient.v3.HttpClient3Instrumentation 2023-11-14 13:23:38,393 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.httpclient.v4.ApacheHttpClientInstrumentation 2023-11-14 13:23:38,393 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.httpclient.v4.ApacheHttpAsyncClientInstrumentation 2023-11-14 13:23:38,393 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.httpclient.v4.ApacheHttpAsyncClientRedirectInstrumentation 2023-11-14 13:23:38,393 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.httpclient.v4.LegacyApacheHttpClientInstrumentation ... (all not applied instrumentations) 2023-11-14 13:23:38,415 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.awssdk.v2.GetMessagesInstrumentation 2023-11-14 13:23:38,415 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.awssdk.v2.AmazonSQSMessagingClientWrapperInstrumentation 2023-11-14 13:23:38,415 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.finaglehttpclient.FinaglePayloadSizeFilterInstrumentation 2023-11-14 13:23:38,415 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.finaglehttpclient.FinagleExceptionSourceFilterInstrumentation 2023-11-14 13:23:38,415 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.finaglehttpclient.FinagleTlsFilterInstrumentation 2023-11-14 13:23:38,415 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.java_ldap.LdapClientInstrumentation 2023-11-14 13:23:38,415 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation com.xxx.eclipse_milo_apm_plugin.SendRequestInstrumentation 2023-11-14 13:23:38,415 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation com.xxx.tibco_apm_plugin.TibcoRequestInstrumentation 2023-11-14 13:23:38,458 [elastic-apm-metadata-0] DEBUG co.elastic.apm.agent.impl.metadata.SystemInfo - hostname obtained by executing command "powershell.exe [System.Net.Dns]::GetHostEntry($env:computerName).HostName": xxx 2023-11-14 13:23:38,458 [elastic-apm-metadata-0] DEBUG co.elastic.apm.agent.impl.metadata.SystemInfo - Could not parse container ID from '\proc\self\cgroup' 2023-11-14 13:23:38,459 [elastic-apm-metadata-0] DEBUG co.elastic.apm.agent.impl.metadata.SystemInfo - Could not parse container ID from '\proc\self\mountinfo' 2023-11-14 13:23:38,459 [elastic-apm-metadata-0] DEBUG co.elastic.apm.agent.impl.metadata.SystemInfo - container ID is null 2023-11-14 13:23:38,528 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation com.xxx.tibco_apm_plugin.TibcoSendInstrumentation 2023-11-14 13:23:38,529 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation com.xxx.tibco_apm_plugin.TibcoListenerInstrumentation 2023-11-14 13:23:38,530 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applied 3 advices 2023-11-14 13:23:38,623 [main] WARN co.elastic.apm.agent.bci.bytebuddy.InstallationListenerImpl - Byte Buddy warmup ended without transforming at least one class. The agent may not work as expected. 2023-11-14 13:23:41,175 [main] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-server-healthcheck` was created. The original context class loader of this thread (sun.misc.Launcher$AppClassLoader@18b4aac2) has been overridden 2023-11-14 13:23:41,176 [main] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-server-reporter` was created. The original context class loader of this thread (sun.misc.Launcher$AppClassLoader@18b4aac2) has been overridden 2023-11-14 13:23:41,178 [elastic-apm-server-healthcheck] DEBUG co.elastic.apm.agent.util.UrlConnectionUtils - Opening http://xxxx:8200/ without proxy 2023-11-14 13:23:41,179 [main] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-remote-config-poller` was created. The original context class loader of this thread (sun.misc.Launcher$AppClassLoader@18b4aac2) has been overridden 2023-11-14 13:23:41,181 [elastic-apm-server-healthcheck] DEBUG co.elastic.apm.agent.report.ApmServerHealthChecker - Starting healthcheck to http://xxxx:8200/ 2023-11-14 13:23:42,581 [main] DEBUG co.elastic.apm.agent.impl.circuitbreaker.GCStressMonitor - Registering a heap memory pool (PS Eden Space) for stress monitoring 2023-11-14 13:23:42,581 [main] DEBUG co.elastic.apm.agent.impl.circuitbreaker.GCStressMonitor - Registering a heap memory pool (PS Old Gen) for stress monitoring 2023-11-14 13:23:42,582 [main] DEBUG co.elastic.apm.agent.impl.circuitbreaker.SystemCpuStressMonitor - Successfully obtained reference to the getSystemCpuLoad method of this JVM's OperatingSystemMXBean implementation 2023-11-14 13:23:42,583 [main] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-circuit-breaker` was created. The original context class loader of this thread (sun.misc.Launcher$AppClassLoader@18b4aac2) has been overridden 2023-11-14 13:23:42,584 [main] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-weak-map-cleaner` was created. The original context class loader of this thread (sun.misc.Launcher$AppClassLoader@18b4aac2) has been overridden 2023-11-14 13:23:42,584 [main] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-shared` was created. The original context class loader of this thread (sun.misc.Launcher$AppClassLoader@18b4aac2) has been overridden 2023-11-14 13:23:42,585 [main] DEBUG co.elastic.apm.agent.jmx.JmxMetricTracker - Deferring initialization of JMX metric tracking until capture_jmx_metrics option is set 2023-11-14 13:23:42,585 [main] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-sampling-profiler` was created. The original context class loader of this thread (sun.misc.Launcher$AppClassLoader@18b4aac2) has been overridden 2023-11-14 13:23:42,587 [main] INFO co.elastic.apm.agent.impl.ElasticApmTracer - Tracer switched to RUNNING state 2023-11-14 13:23:43,868 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation TibcoListenerInstrumentation: (hasSuperType(erasure(name(equals(com.tibco.tibrv.TibrvMsgCallback)))) and not(isInterface())) matches class xxx.components.bus.tibrv.ASysServiceHandler 2023-11-14 13:23:43,938 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation TibcoListenerInstrumentation: (name(equals(onMsg)) and not(isAbstract())) matches public void xxx.components.bus.tibrv.ASysServiceHandler.onMsg(com.tibco.tibrv.TibrvListener,com.tibco.tibrv.TibrvMsg) 2023-11-14 13:23:43,982 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation TibcoListenerInstrumentation: (hasSuperType(erasure(name(equals(com.tibco.tibrv.TibrvMsgCallback)))) and not(isInterface())) matches class xxx.components.bus.tibrv.CSysServiceHandlerSysCtrl 2023-11-14 13:23:43,987 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation TibcoListenerInstrumentation: (hasSuperType(erasure(name(equals(com.tibco.tibrv.TibrvMsgCallback)))) and not(isInterface())) matches class xxx.components.bus.tibrv.CSysServiceHandlerStd 2023-11-14 13:23:43,991 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation TibcoListenerInstrumentation: (name(equals(onMsg)) and not(isAbstract())) matches public void xxx.components.bus.tibrv.CSysServiceHandlerStd.onMsg(com.tibco.tibrv.TibrvListener,com.tibco.tibrv.TibrvMsg) 2023-11-14 13:23:43,994 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation TibcoRequestInstrumentation: name(equals(com.tibco.tibrv.TibrvTransport)) matches class com.tibco.tibrv.TibrvTransport 2023-11-14 13:23:43,994 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation TibcoSendInstrumentation: name(equals(com.tibco.tibrv.TibrvTransport)) matches class com.tibco.tibrv.TibrvTransport 2023-11-14 13:23:44,013 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation TibcoSendInstrumentation: (name(equals(send)) and not(isAbstract())) matches public void com.tibco.tibrv.TibrvTransport.send(com.tibco.tibrv.TibrvMsg) throws com.tibco.tibrv.TibrvException 2023-11-14 13:23:44,016 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation TibcoRequestInstrumentation: (name(equals(sendRequest)) and not(isAbstract())) matches public com.tibco.tibrv.TibrvMsg com.tibco.tibrv.TibrvTransport.sendRequest(com.tibco.tibrv.TibrvMsg,double) throws com.tibco.tibrv.TibrvException 2023-11-14 13:23:44,023 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation TibcoListenerInstrumentation: (hasSuperType(erasure(name(equals(com.tibco.tibrv.TibrvMsgCallback)))) and not(isInterface())) matches class xxx.components.bus.tibrv.CSysServiceHandlerDq 2023-11-14 13:24:01,211 [elastic-apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server http://xxxx:8200/config/v1/agents 2023-11-14 13:24:05,185 [elastic-apm-init-instrumentation-shutdown-hook] INFO co.elastic.apm.agent.bci.InstrumentationStatsLifecycleListener - Used instrumentation groups: [tibcorv] 2023-11-14 13:24:05,186 [elastic-apm-init-instrumentation-shutdown-hook] DEBUG co.elastic.apm.agent.bci.InstrumentationStatsLifecycleListener - Total time spent matching: 2.773.688.000ns
Shaoranlaos commented 11 months ago

Had forgotten to also add the opentelemetry instrumentation. Plugins are working of of that for there instrumentation so it must also be enabled.