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.

Sign up for GitHub

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

Jump to bottom

Elastic APM agent duplicates all logs for any Quarkus application starting with version 1.30.0 #3563

Closed
alejavigo opened this issue Mar 14, 2024 · 2 comments
Closed

Elastic APM agent duplicates all logs for any Quarkus application starting with version 1.30.0 #3563

alejavigo opened this issue Mar 14, 2024 · 2 comments
Labels
agent-java community Issues and PRs created by the community

Comments

@alejavigo
Copy link

Describe the bug

Launching a Quarkus application with apm agent version >=1.30 will have its logs duplicated.
Tried from last version down to 1.29.0 where the problem is not there anymore.

Steps to reproduce

Get basic quarkus demo app like https://github.com/quarkusio/quarkus-quickstarts/tree/main/getting-started
Instrument app with: mvn quarkus:dev -Djvm.args=-javaagent:path_to_elastic-apm-agent-1.48.1.jar

find this in console:
2024-03-14 19:21:09,619 INFO [io.quarkus] (Quarkus Main Thread) getting-started 1.0.0-SNAPSHOT on JVM (powered by Quarkus 3.8.2) started in 1.572s. Listening on: http://localhost:8080
2024-03-14T19:21:09+01:00 INFO [io.quarkus] (Quarkus Main Thread) getting-started 1.0.0-SNAPSHOT on JVM (powered by Quarkus 3.8.2) started in 1.572s. Listening on: http://localhost:8080

Date pattern and class name format are different for the duplicated log (the second one) from the expected quarkus format log (the first one)

Tried all kind of configurations, disabling all instrumenting, disabling logging, setting agent log level to ALL and analyzing it.

Expected behavior

Normal logs for the quarkus app, not duplicated

Debug logs

Click to expand 
2024-03-14 19:21:06,665 [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 (jdk.internal.loader.ClassLoaders$AppClassLoader@5e2de80c) has been overridden
2024-03-14 19:21:06,698 [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 (jdk.internal.loader.ClassLoaders$AppClassLoader@5e2de80c) has been overridden
2024-03-14 19:21:06,699 [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 (jdk.internal.loader.ClassLoaders$AppClassLoader@5e2de80c) has been overridden
2024-03-14 19:21:06,701 [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=jdk.internal.loader.ClassLoaders$PlatformClassLoader@16f7c8c1, customPrefix='cached-lookup-key/', manifest=java.util.jar.Manifest@bfec9f50, jarUrl=file:/C:/elastic_apm/elastic-apm-agent-1.48.1.jar}, customPrefix='agent/', manifest=java.util.jar.Manifest@bfec9f50, jarUrl=file:/C:/elastic_apm/elastic-apm-agent-1.48.1.jar}) has been overridden
2024-03-14 19:21:06,701 [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=jdk.internal.loader.ClassLoaders$PlatformClassLoader@16f7c8c1, customPrefix='cached-lookup-key/', manifest=java.util.jar.Manifest@bfec9f50, jarUrl=file:/C:/elastic_apm/elastic-apm-agent-1.48.1.jar}, customPrefix='agent/', manifest=java.util.jar.Manifest@bfec9f50, jarUrl=file:/C:/elastic_apm/elastic-apm-agent-1.48.1.jar}) has been overridden
2024-03-14 19:21:06,702 [elastic-apm-cloud-metadata-0] DEBUG co.elastic.apm.agent.util.UrlConnectionUtils - Opening http://169.254.169.254/latest/api/token without proxy
2024-03-14 19:21:06,706 [elastic-apm-cloud-metadata-1] DEBUG co.elastic.apm.agent.util.UrlConnectionUtils - Opening http://metadata.google.internal/computeMetadata/v1/?recursive=true without proxy
2024-03-14 19:21:06,706 [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
2024-03-14 19:21:06,712 [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
2024-03-14 19:21:06,729 [main] INFO  co.elastic.apm.agent.util.JmxUtils - Found JVM-specific OperatingSystemMXBean interface: com.sun.management.OperatingSystemMXBean
2024-03-14 19:21:06,730 [main] DEBUG co.elastic.apm.agent.metrics.builtin.CGroupMetrics - Cannot find/read /proc/self/cgroup file. Cgroup metrics will not be reported.
2024-03-14 19:21:06,738 [main] INFO  co.elastic.apm.agent.util.JmxUtils - Found JVM-specific ThreadMXBean interface: com.sun.management.ThreadMXBean
2024-03-14 19:21:06,746 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - Starting Elastic APM 1.48.1 as vdr on Java 17.0.7 Runtime version: 17.0.7+7 VM version: 17.0.7+7 (Eclipse Adoptium) Windows 10 10.0
2024-03-14 19:21:06,746 [main] DEBUG co.elastic.apm.agent.configuration.StartupInfo - VM Arguments: [-javaagent:../../datachain-load-testing-tools/elastic_apm/elastic-apm-agent-1.48.1.jar, -Dquarkus-internal.serialized-app-model.path=C:\quarkus-quickstarts\getting-started\target\quarkus\bootstrap\dev-app-model.dat, -javaagent:C:\.m2\repository\io\quarkus\quarkus-class-change-agent\3.8.2\quarkus-class-change-agent-3.8.2.jar, -XX:TieredStopAtLevel=1, -agentlib:jdwp=transport=dt_socket,address=localhost:5005,server=y,suspend=n, -Djava.util.logging.manager=org.jboss.logmanager.LogManager]
2024-03-14 19:21:06,746 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - instrument: 'false' (source: C:\datachain-load-testing-tools\elastic_apm/elasticapm.properties)
2024-03-14 19:21:06,746 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - service_name: 'vdr' (source: C:\datachain-load-testing-tools\elastic_apm/elasticapm.properties)
2024-03-14 19:21:06,746 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - disable_instrumentations: 'log-correlation, log-error, log-reformatting, logging' (source: C:\datachain-load-testing-tools\elastic_apm/elasticapm.properties)
2024-03-14 19:21:06,746 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - application_packages: 'com.stellantis.flr' (source: C:\datachain-load-testing-tools\elastic_apm/elasticapm.properties)
2024-03-14 19:21:06,746 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - log_level: 'DEBUG' (source: C:\datachain-load-testing-tools\elastic_apm/elasticapm.properties)
2024-03-14 19:21:06,747 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - No plugins dir
2024-03-14 19:21:06,806 [elastic-apm-metadata-1] DEBUG co.elastic.apm.agent.impl.metadata.CloudMetadataProvider - cloud_provider configured AUTO, no cloud metadata discovered
2024-03-14 19:21:06,968 [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 (jdk.internal.loader.ClassLoaders$AppClassLoader@5e2de80c) has been overridden
2024-03-14 19:21:06,970 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.bbwarmup.WarmupInstrumentation
2024-03-14 19:21:06,983 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.httpclient.v3.HttpClient3Instrumentation
2024-03-14 19:21:06,983 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.httpclient.v4.ApacheHttpClientInstrumentation
2024-03-14 19:21:06,983 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.httpclient.v4.ApacheHttpAsyncClientInstrumentation
2024-03-14 19:21:06,983 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.httpclient.v4.ApacheHttpAsyncClientRedirectInstrumentation
2024-03-14 19:21:06,983 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.httpclient.v4.LegacyApacheHttpClientInstrumentation
2024-03-14 19:21:06,983 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.httpclient.v5.ApacheHttpClient5Instrumentation
2024-03-14 19:21:06,983 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.httpclient.v5.ApacheHttpAsyncClient5Instrumentation
2024-03-14 19:21:06,983 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.ElasticApmApiInstrumentation$StartTransactionInstrumentation
2024-03-14 19:21:06,983 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.ElasticApmApiInstrumentation$StartTransactionWithRemoteParentInstrumentation
2024-03-14 19:21:06,983 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.ElasticApmApiInstrumentation$CurrentTransactionInstrumentation
2024-03-14 19:21:06,983 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.ElasticApmApiInstrumentation$CurrentSpanInstrumentation
2024-03-14 19:21:06,983 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.ElasticApmApiInstrumentation$CaptureExceptionInstrumentation
2024-03-14 19:21:06,984 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.ElasticApmApiInstrumentation$SetServiceInfoForClassLoaderInstrumentation
2024-03-14 19:21:06,984 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.ElasticApmApiInstrumentation$ConfigInstrumentation
2024-03-14 19:21:06,984 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.TransactionInstrumentation$SetFrameworkNameInstrumentation
2024-03-14 19:21:06,984 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.TransactionInstrumentation$SetUserInstrumentation
2024-03-14 19:21:06,984 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.TransactionInstrumentation$EnsureParentIdInstrumentation
2024-03-14 19:21:06,984 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.TransactionInstrumentation$SetResultInstrumentation
2024-03-14 19:21:06,984 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.TransactionInstrumentation$AddCustomContextInstrumentation
2024-03-14 19:21:06,984 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.TransactionInstrumentation$SetServiceInfoInstrumentation
2024-03-14 19:21:06,984 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.TransactionInstrumentation$UseServiceInfoForClassLoaderInstrumentation
2024-03-14 19:21:06,984 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$SetNameInstrumentation
2024-03-14 19:21:06,984 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$SetTypeInstrumentation
2024-03-14 19:21:06,984 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$SetTypesInstrumentation
2024-03-14 19:21:06,985 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$DoCreateSpanInstrumentation
2024-03-14 19:21:06,985 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$DoCreateExitSpanInstrumentation
2024-03-14 19:21:06,985 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$InitializeInstrumentation
2024-03-14 19:21:06,985 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$SetStartTimestampInstrumentation
2024-03-14 19:21:06,985 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$SetOutcomeInstrumentation
2024-03-14 19:21:06,985 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$EndInstrumentation
2024-03-14 19:21:06,985 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$EndWithTimestampInstrumentation
2024-03-14 19:21:06,985 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$CaptureExceptionInstrumentation
2024-03-14 19:21:06,985 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$GetIdInstrumentation
2024-03-14 19:21:06,985 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$GetTraceIdInstrumentation
2024-03-14 19:21:06,985 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$AddStringLabelInstrumentation
2024-03-14 19:21:06,985 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$AddNumberLabelInstrumentation
2024-03-14 19:21:06,986 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$AddBooleanLabelInstrumentation
2024-03-14 19:21:06,986 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$ActivateInstrumentation
2024-03-14 19:21:06,986 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$IsSampledInstrumentation
2024-03-14 19:21:06,986 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$InjectTraceHeadersInstrumentation
2024-03-14 19:21:06,986 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$SetDestinationAddressInstrumentation
2024-03-14 19:21:06,986 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$SetDestinationServiceInstrumentation
2024-03-14 19:21:06,986 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$SetServiceTargetInstrumentation
2024-03-14 19:21:06,986 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$SetNonDiscardableInstrumentation
2024-03-14 19:21:06,986 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.CaptureExceptionInstrumentation
2024-03-14 19:21:06,986 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.ApiScopeInstrumentation
2024-03-14 19:21:06,986 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.pluginapi.CaptureTransactionInstrumentation
2024-03-14 19:21:06,986 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.pluginapi.CaptureSpanInstrumentation
2024-03-14 19:21:06,986 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Not applying excluded instrumentation co.elastic.apm.agent.pluginapi.TracedInstrumentation
2024-03-14 19:21:06,986 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.AbstractSpanInstrumentation$LegacyCaptureExceptionInstrumentation
2024-03-14 19:21:06,987 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.LegacySpanInstrumentation$SetNameInstrumentation
2024-03-14 19:21:06,987 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.LegacySpanInstrumentation$SetTypeInstrumentation
2024-03-14 19:21:06,987 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.LegacySpanInstrumentation$DoCreateSpanInstrumentation
2024-03-14 19:21:06,987 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.LegacySpanInstrumentation$EndInstrumentation
2024-03-14 19:21:06,987 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.LegacySpanInstrumentation$CaptureExceptionInstrumentation
2024-03-14 19:21:06,987 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.LegacySpanInstrumentation$GetIdInstrumentation
2024-03-14 19:21:06,987 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.LegacySpanInstrumentation$GetTraceIdInstrumentation
2024-03-14 19:21:06,987 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.LegacySpanInstrumentation$AddTagInstrumentation
2024-03-14 19:21:06,988 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.LegacySpanInstrumentation$ActivateInstrumentation
2024-03-14 19:21:06,988 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.pluginapi.LegacySpanInstrumentation$IsSampledInstrumentation
*****
Removed because of size
******
2024-03-14 19:21:06,997 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applied 73 advices
2024-03-14 19:21:07,017 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation WarmupInstrumentation: name(equals(co.elastic.apm.agent.bci.bytebuddy.Instrumented)) matches class co.elastic.apm.agent.bci.bytebuddy.Instrumented
2024-03-14 19:21:07,044 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation WarmupInstrumentation: (not(isStatic()) and name(equals(isInstrumented)) and hasParameter(ofSize(0)) and returns(erasure(is(boolean))) and not(isAbstract())) matches public boolean co.elastic.apm.agent.bci.bytebuddy.Instrumented.isInstrumented()
2024-03-14 19:21:07,063 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation WarmupInstrumentation: name(equals(co.elastic.apm.agent.bci.bytebuddy.Instrumented)) matches class co.elastic.apm.agent.bci.bytebuddy.Instrumented
2024-03-14 19:21:07,065 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation WarmupInstrumentation: (not(isStatic()) and name(equals(isInstrumented)) and hasParameter(ofSize(0)) and returns(erasure(is(boolean))) and not(isAbstract())) matches public boolean co.elastic.apm.agent.bci.bytebuddy.Instrumented.isInstrumented()
2024-03-14 19:21:07,066 [main] DEBUG co.elastic.apm.agent.bci.bytebuddy.InstallationListenerImpl - Warmup: bytecode transformation of co.elastic.apm.agent.bci.bytebuddy.Instrumented succeeded
2024-03-14 19:21:07,087 [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": local
2024-03-14 19:21:07,088 [elastic-apm-metadata-0] DEBUG co.elastic.apm.agent.impl.metadata.SystemInfo - Could not parse container ID from '\proc\self\cgroup'
2024-03-14 19:21:07,088 [elastic-apm-metadata-0] DEBUG co.elastic.apm.agent.impl.metadata.SystemInfo - Could not parse container ID from '\proc\self\mountinfo'
2024-03-14 19:21:07,088 [elastic-apm-metadata-0] DEBUG co.elastic.apm.agent.impl.metadata.SystemInfo - container ID is null
2024-03-14 19:21:07,095 [main] DEBUG co.elastic.apm.agent.bci.IndyPluginClassLoaderFactory - Creating plugin class loader for net.bytebuddy.dynamic.loading.ByteArrayClassLoader$ChildFirst@472698d containing [co.elastic.apm.agent.bbwarmup.package-info, co.elastic.apm.agent.bbwarmup.WarmupInstrumentation$AdviceClass, co.elastic.apm.agent.bbwarmup.WarmupInstrumentation, co.elastic.apm.agent.bci.classloading.LookupExposer]
2024-03-14 19:21:07,096 [main] DEBUG co.elastic.apm.agent.bci.bytebuddy.InstallationListenerImpl - Warmup: instrumented bytecode of co.elastic.apm.agent.bci.bytebuddy.Instrumented was executed as expected
2024-03-14 19:21:07,103 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation WarmupInstrumentation: name(equals(co.elastic.apm.agent.bci.bytebuddy.Instrumented)) matches class co.elastic.apm.agent.bci.bytebuddy.Instrumented
2024-03-14 19:21:07,149 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation WarmupInstrumentation: name(equals(co.elastic.apm.agent.bci.bytebuddy.Instrumented)) matches class co.elastic.apm.agent.bci.bytebuddy.Instrumented
2024-03-14 19:21:07,152 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation WarmupInstrumentation: (not(isStatic()) and name(equals(isInstrumented)) and hasParameter(ofSize(0)) and returns(erasure(is(boolean))) and not(isAbstract())) matches public boolean co.elastic.apm.agent.bci.bytebuddy.Instrumented.isInstrumented()
2024-03-14 19:21:07,158 [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 (jdk.internal.loader.ClassLoaders$AppClassLoader@5e2de80c) has been overridden
2024-03-14 19:21:07,158 [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 (jdk.internal.loader.ClassLoaders$AppClassLoader@5e2de80c) has been overridden
2024-03-14 19:21:07,159 [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 (jdk.internal.loader.ClassLoaders$AppClassLoader@5e2de80c) has been overridden
2024-03-14 19:21:07,159 [elastic-apm-server-healthcheck] DEBUG co.elastic.apm.agent.util.UrlConnectionUtils - Opening http://127.0.0.1:8200/ without proxy
2024-03-14 19:21:07,160 [elastic-apm-server-healthcheck] DEBUG co.elastic.apm.agent.report.ApmServerHealthChecker - Starting healthcheck to http://127.0.0.1:8200/
2024-03-14 19:21:07,198 [elastic-apm-server-healthcheck] WARN  co.elastic.apm.agent.report.ApmServerHealthChecker - Elastic APM server http://127.0.0.1:8200/ is not available (Connection refused: no further information)
2024-03-14 19:21:07,199 [elastic-apm-remote-config-poller] DEBUG co.elastic.apm.agent.util.UrlConnectionUtils - Opening http://127.0.0.1:8200/config/v1/agents without proxy
2024-03-14 19:21:07,199 [elastic-apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server http://127.0.0.1:8200/config/v1/agents
2024-03-14 19:21:07,200 [elastic-apm-remote-config-poller] DEBUG co.elastic.apm.agent.report.ApmServerClient - Exception while interacting with APM Server, trying next one.
2024-03-14 19:21:07,200 [elastic-apm-remote-config-poller] ERROR co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Connection refused: no further information
2024-03-14 19:21:07,200 [elastic-apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 300s
2024-03-14 19:21:07,601 [main] DEBUG co.elastic.apm.agent.impl.circuitbreaker.GCStressMonitor - Registering a heap memory pool (G1 Eden Space) for stress monitoring
2024-03-14 19:21:07,601 [main] DEBUG co.elastic.apm.agent.impl.circuitbreaker.GCStressMonitor - Registering a heap memory pool (G1 Old Gen) for stress monitoring
2024-03-14 19:21:07,602 [main] DEBUG co.elastic.apm.agent.impl.circuitbreaker.SystemCpuStressMonitor - Successfully obtained reference to the getSystemCpuLoad method of this JVM's OperatingSystemMXBean implementation
2024-03-14 19:21:07,602 [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 (jdk.internal.loader.ClassLoaders$AppClassLoader@5e2de80c) has been overridden
2024-03-14 19:21:07,602 [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 (jdk.internal.loader.ClassLoaders$AppClassLoader@5e2de80c) has been overridden
2024-03-14 19:21:07,602 [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 (jdk.internal.loader.ClassLoaders$AppClassLoader@5e2de80c) has been overridden
2024-03-14 19:21:07,602 [main] DEBUG co.elastic.apm.agent.jmx.JmxMetricTracker - Deferring initialization of JMX metric tracking until capture_jmx_metrics option is set
2024-03-14 19:21:07,603 [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 (jdk.internal.loader.ClassLoaders$AppClassLoader@5e2de80c) has been overridden
2024-03-14 19:21:07,603 [main] INFO  co.elastic.apm.agent.impl.ElasticApmTracer - Tracer switched to RUNNING state
@github-actions github-actions bot added agent-java community Issues and PRs created by the community triage labels Mar 14, 2024
@alejavigo alejavigo mentioned this issue Mar 14, 2024
Merged
20 tasks
@JonasKunz JonasKunz mentioned this issue Apr 2, 2024
Closed
@JonasKunz
Copy link
Contributor

Thanks for providing the details on how to reproduce.

The change that triggers this duplication was actually introduced in #2460. The logging instrumentation is unrelated, the problem also occurs with elastic.apm.instrument set to false.

My hypothesis of what's happening here is that quarkus wrongly picks up the log4j2 configuration used by the agent internally. The agent runs in its own classloader with it's own isolated copy of log4j2 and an isolated configuration file.
Quarkus seems to somehow use the thread context-classloaders to pick up logging configurations. It even does so wrongly for elastic apm agent internal threads, which should be none of its business.

The problem doesn't occur anymore if we don't set the thread context classloaders (you can test with #3575). However, this is nothing we will change in our agent because we set the context classloader for a reason.

Instead I'd recommend you to open an issue at the Quarkus repo: Quarkus shouldn't care about context-classloaders and their log4j2-configs for javaagents.

I'm closing this issue for now, as it is rather is a problem with the Quarkus implementation and nothing we'll fix in our agent.

@JonasKunz JonasKunz removed the triage label Apr 2, 2024
@alejavigo alejavigo mentioned this issue Apr 11, 2024
Closed
@alejavigo
Copy link
Author

Opened jira on Quarkus side:
quarkusio/quarkus#40009

@dmlloyd dmlloyd mentioned this issue Apr 15, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
agent-java community Issues and PRs created by the community
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@JonasKunz @alejavigo