Java agent in IBM Websphere 8.5.5 not send events

fernandezsjanto · May 11, 2021, 11:50am

Kibana version:
7.10.1
Elasticsearch version:
7.10.1
APM Server version:
7.10.2
APM Agent language and version:
java 1.23.0
Browser version:

Original install method (e.g. download page, yum, deb, from source, etc.) and version:
download page
Fresh install or upgraded from other version?
Fresh install
Is there anything special in your setup? For example, are you using the Logstash or Kafka outputs? Are you using a load balancer in front of the APM Servers? Have you changed index pattern, generated custom templates, changed agent configuration etc.

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):
The agent is installed on an instance of websphere 8.5.5.19, running on an IBM java 1.8_64 virtual machine.

The agent configuration is as follows:
'''
-javaagent: L: \ path \ elastic-apm-agent.jar
-Delastic.apm.service_name = 18corporatives
-Delastic.apm.environment = DEVELOPMENT
-Delastic.apm.server_url = http: // url: 8200
-Delastic.apm. log_file = L: /path/elastic-apm-agent_18corporativas.log -Delastic.apm.application_packages = es.iam
'''
The agent does not send the instrumentation events to the server, the VM metrics if they arrive correctly.

The following entries appear in the agent log:
'''
WARN co.elastic.apm.agent.bci.bytebuddy.ErrorLoggingListener - org.apache.commons.discovery.jdk.PsuedoSystemClassLoader uses an unsupported class file version (pre Java 4}) and can't be instrumented. Consider updating to a newer version of that library.
2021-05-10 11: 43: 10,014 [server.startup: 1] WARN co.elastic.apm.agent.bci.bytebuddy.ErrorLoggingListener - org.slf4j.helpers.NamedLoggerBase uses an unsupported class file version (pre Java 4} ) and can't be instrumented. Consider updating to a newer version of that library.
2021-05-10 11: 43: 27,229 [server.startup: 0] WARN co.elastic.apm.agent.bci.bytebuddy.ErrorLoggingListener - org.slf4j.impl.Log4jLoggerAdapter uses an unsupported class file version (pre Java 4} ) and can't be instrumented. Consider updating to a newer version of that library.
2021-05-10 11: 43: 27,229 [server.startup: 0] WARN co.elastic.apm.agent.bci.bytebuddy.ErrorLoggingListener - org.slf4j.helpers.NamedLoggerBase uses an unsupported class file version (pre Java 4} ) and can't be instrumented. Consider updating to a newer version of that library.
2021-05-10 11: 43: 29,246 [server.startup: 0] WARN co.elastic.apm.agent.bci.bytebuddy.ErrorLoggingListener - org.slf4j.impl.SimpleLogger uses an unsupported class file version (pre Java 4} ) and can't be instrumented. Consider updating to a newer version of that library.
2021-05-10 11: 43: 29,261 [server.startup: 0] WARN co.elastic.apm.agent.bci.bytebuddy.ErrorLoggingListener - org.slf4j.helpers.NamedLoggerBase uses an unsupported class file version (pre Java 4} ) and can't be instrumented. Consider updating to a newer version of that library.
'''
but there are no more errors

Any ideas on how to fix it?
Steps to reproduce:
1.
2.
3.

Errors in browser console (if relevant):

Provide logs and/or server output (if relevant):

Sylvain_Juge · May 11, 2021, 12:16pm

Hi @fernandezsjanto ,

Can you provide the first lines of the agent log ?

Those lines should contain the non-default parameter values used by the agent, that allows to check for any difference (for example parsing error) with the values that you have set through configuration. Also, configuration could be set at multiple levels and overriden (see doc
)

Regarding those warning messages, they are related to trying to instrument very old java bytecode. Given that only slf4j seems impacted there should be no consequence here, unless you try to use log correlation, in which case the feature might not work (agent has to instrument logger library in order to inject current transaction/span ID into logs).
Upgrading to a newer version of slf4j library is the most straightforward way to deal with this for now.

fernandezsjanto · May 11, 2021, 12:58pm

Hi,
I have activated the DEBUG level in the log and the result is the following:

2021-05-11 13:21:42,025 [main] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-metadata` was created. The original context class loader of this thread (sun.misc.Launcher$AppClassLoader@5a301f5b) has been overridden
2021-05-11 13:21:42,025 [elastic-apm-metadata] 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 (null) has been overridden
2021-05-11 13:21:42,025 [elastic-apm-metadata] 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 (null) has been overridden
2021-05-11 13:21:42,056 [main] INFO  co.elastic.apm.agent.util.JmxUtils - Found JVM-specific OperatingSystemMXBean interface: com.ibm.lang.management.OperatingSystemMXBean
2021-05-11 13:21:42,056 [main] DEBUG co.elastic.apm.agent.metrics.builtin.CGroupMetrics - Cannot find/read /proc/self/cgroup file. Cgroup metrics will not be reported.
2021-05-11 13:21:42,072 [main] DEBUG co.elastic.apm.agent.util.ExecutorUtils - A new thread named `elastic-apm-log-shipper` was created. The original context class loader of this thread (sun.misc.Launcher$AppClassLoader@5a301f5b) has been overridden
2021-05-11 13:21:42,072 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - Starting Elastic APM 1.23.0 as 18corporativos on Java 1.8.0_261 Runtime version: 8.0.6.15 - pwa6480sr6fp15ifix-20200820_01(SR6 FP15+IJ26443) VM version: 2.9 (IBM Corporation) Windows Server 2012 R2 6.3
2021-05-11 13:21:42,072 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - VM Arguments: [-Xoptionsfile=C:\WebSphere85\AppServer\java_1.8_64\jre\bin\compressedrefs\options.default, -Xlockword:mode=default,noLockword=java/lang/String,noLockword=java/util/MapEntry,noLockword=java/util/HashMap$Entry,noLockword=org/apache/harmony/luni/util/ModifiedMap$Entry,noLockword=java/util/Hashtable$Entry,noLockword=java/lang/invoke/MethodType,noLockword=java/lang/invoke/MethodHandle,noLockword=java/lang/invoke/CollectHandle,noLockword=java/lang/invoke/ConstructorHandle,noLockword=java/lang/invoke/ConvertHandle,noLockword=java/lang/invoke/ArgumentConversionHandle,noLockword=java/lang/invoke/AsTypeHandle,noLockword=java/lang/invoke/ExplicitCastHandle,noLockword=java/lang/invoke/FilterReturnHandle,noLockword=java/lang/invoke/DirectHandle,noLockword=java/lang/invoke/ReceiverBoundHandle,noLockword=java/lang/invoke/DynamicInvokerHandle,noLockword=java/lang/invoke/FieldHandle,noLockword=java/lang/invoke/FieldGetterHandle,noLockword=java/lang/invoke/FieldSetterHandle,noLockword=java/lang/invoke/StaticFieldGetterHandle,noLockword=java/lang/invoke/StaticFieldSetterHandle,noLockword=java/lang/invoke/IndirectHandle,noLockword=java/lang/invoke/InterfaceHandle,noLockword=java/lang/invoke/VirtualHandle,noLockword=java/lang/invoke/PrimitiveHandle,noLockword=java/lang/invoke/InvokeExactHandle,noLockword=java/lang/invoke/InvokeGenericHandle,noLockword=java/lang/invoke/VarargsCollectorHandle,noLockword=java/lang/invoke/ThunkTuple, -Djava.lang.stringBuffer.growAggressively=false, -XX:+OriginalJDK8HeapSizeCompatibilityMode, -Xjcl:jclse29, -Dcom.ibm.oti.vm.bootstrap.library.path=C:\WebSphere85\AppServer\java_1.8_64\jre\bin\compressedrefs;C:\WebSphere85\AppServer\java_1.8_64\jre\bin, -Dsun.boot.library.path=C:\WebSphere85\AppServer\java_1.8_64\jre\bin\compressedrefs;C:\WebSphere85\AppServer\java_1.8_64\jre\bin, -Djava.library.path=C:\WebSphere85\AppServer\java_1.8_64\jre\bin\compressedrefs;C:\WebSphere85\AppServer\java_1.8_64\jre\bin;C:\Windows\system32;C:\Windows;C:\WebSphere85\AppServer\lib\native\win\x86_64;C:\WebSphere85\AppServer\bin;C:\WebSphere85\AppServer\java\bin;C:\WebSphere85\AppServer\java\jre\bin;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\bibliotecas8\SAPJCO;., -Djava.home=C:\WebSphere85\AppServer\java_1.8_64\jre, -Djava.ext.dirs=C:\WebSphere85\AppServer\java_1.8_64\jre\lib\ext, -Duser.dir=C:\WebSphere85\AppServer\profiles\Nodo01, -Djava.runtime.version=pwa6480sr6fp15ifx-20200820_01 (SR6 FP15+IJ26443), -Dconsole.encoding=Cp850, -Djava.class.path=C:\WebSphere85\AppServer\profiles\Nodo01\properties;C:\WebSphere85\AppServer\properties;C:\WebSphere85\AppServer\lib\startup.jar;C:\WebSphere85\AppServer\lib\bootstrap.jar;C:\WebSphere85\AppServer/lib/lmproxy.jar;C:\WebSphere85\AppServer/lib/urlprotocols.jar;C:\WebSphere85\AppServer\java\lib\tools.jar, -Dosgi.install.area=C:\WebSphere85\AppServer, -Dosgi.configuration.area=C:\WebSphere85\AppServer\profiles\Nodo01/servers/18corporativos_03/configuration, -Dosgi.framework.extensions=com.ibm.cds,com.ibm.ws.eclipse.adaptors, -Xshareclasses:name=webspherev85_1.8_64,nonFatal, -Dsun.reflect.inflationThreshold=250, -Dcom.ibm.xtq.processor.overrideSecureProcessing=true, -Djava.security.properties=C:\WebSphere85\AppServer/properties/java.security, -Xbootclasspath/p:C:\WebSphere85\AppServer/java_1.8_64/jre/lib/ibmorb.jar, -Djava.class.path=C:\WebSphere85\AppServer\profiles\Nodo01/properties;C:\WebSphere85\AppServer/properties;C:\WebSphere85\AppServer/lib/startup.jar;C:\WebSphere85\AppServer/lib/bootstrap.jar;C:\WebSphere85\AppServer/lib/lmproxy.jar;C:\WebSphere85\AppServer/lib/urlprotocols.jar;C:\WebSphere85\AppServer/deploytool/itp/batchboot.jar;C:\WebSphere85\AppServer/deploytool/itp/batch2.jar;C:\WebSphere85\AppServer/java_1.8_64/lib/tools.jar, -Dibm.websphere.internalClassAccessMode=allow, -Xms256m, -Xmx2048m, -Xcompressedrefs, -Xscmaxaot16M, -Xscmx120M, -Dws.ext.dirs=C:\WebSphere85\AppServer/java_1.8_64/lib;C:\WebSphere85\AppServer\profiles\Nodo01/classes;C:\WebSphere85\AppServer/classes;C:\WebSphere85\AppServer/lib;C:\WebSphere85\AppServer/installedChannels;C:\WebSphere85\AppServer/lib/ext;C:\WebSphere85\AppServer/web/help;C:\WebSphere85\AppServer/deploytool/itp/plugins/com.ibm.etools.ejbdeploy/runtime, -Dderby.system.home=C:\WebSphere85\AppServer/derby, -Dcom.ibm.itp.location=C:\WebSphere85\AppServer/bin, -Djava.util.logging.configureByServer=true, -Duser.install.root=C:\WebSphere85\AppServer\profiles\Nodo01, -Djava.ext.dirs=C:\WebSphere85\AppServer/tivoli/tam;C:\WebSphere85\AppServer/java_1.8_64/jre/lib/ext, -Djavax.management.builder.initial=com.ibm.ws.management.PlatformMBeanServerBuilder, -Dpython.cachedir=C:\WebSphere85\AppServer\profiles\Nodo01/temp/cachedir, -Dwas.install.root=C:\WebSphere85\AppServer, -Djava.util.logging.manager=com.ibm.ws.bootstrap.WsLogManager, -Dserver.root=C:\WebSphere85\AppServer\profiles\Nodo01, -DWAS8_LOGS=\\wascfgdesnas\recDESARROLLO\intraRootDes\logs, -DWAS8_SERVER_NAME=18corporativos_03, -DHttpSessionIdReuse=true, -DWAS_TEMPORAL=\\wastmpdesnas\WasTemporalDes\desarrollo, -Djaxws.ignore.extraWSDLOps=true, -Dorg.apache.el.parser.COERCE_TO_ZERO=false, -Djco.destinations.dir=\\wascfgdesnas\recDesarrollo\intraRootDes\recursos, -javaagent:L:\ELKIA-agent\elastic-apm-agent.jar, -Delastic.apm.service_name=18corporativos, -Delastic.apm.environment=DESARROLLO, -Delastic.apm.server_url=http://xxxxxxxx.es:8200, -Delastic.apm.log_file=L:/ELKIA-agent/elastic-apm-agent_18corporativos.log, -Delastic.apm.application_packages=es.iam, -Delastic.apm.log_level=DEBUG, -Djava.library.path=C:\WebSphere85\AppServer/lib/native/win/x86_64/;C:\WebSphere85\AppServer\java_1.8_64\jre\bin\compressedrefs;C:\WebSphere85\AppServer\java_1.8_64\jre\bin;C:\Windows\system32;C:\Windows;C:\WebSphere85\AppServer\lib\native\win\x86_64;C:\WebSphere85\AppServer\bin;C:\WebSphere85\AppServer\java_1.8_64\bin;C:\WebSphere85\AppServer\java_1.8_64\jre\bin;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\bibliotecas8\SAPJCO;.;, -Djava.endorsed.dirs=C:\WebSphere85\AppServer/endorsed_apis;C:\WebSphere85\AppServer/java_1.8_64/jre/lib/endorsed;C:\WebSphere85\AppServer\endorsed_apis;C:\WebSphere85\AppServer\java\jre\lib\endorsed, -Djava.security.auth.login.config=C:\WebSphere85\AppServer\profiles\Nodo01/properties/wsjaas.conf, -Djava.security.policy=C:\WebSphere85\AppServer\profiles\Nodo01/properties/server.policy, -Dsun.java.command=com.ibm.wsspi.bootstrap.WSPreLauncher -nosplash -application com.ibm.ws.bootstrap.WSLauncher com.ibm.ws.runtime.WsServer C:\WebSphere85\AppServer\profiles\Nodo01\config dmgr85desaCelula was8des03Nodo 18corporativos_03, -Dsun.java.launcher=SUN_STANDARD]
2021-05-11 13:21:42,072 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - service_name: '18corporativos' (source: Java System Properties)
2021-05-11 13:21:42,072 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - environment: 'DESARROLLO' (source: Java System Properties)
2021-05-11 13:21:42,072 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - server_url: 'http://elkiaapmdes.munimadrid.es:8200' (source: Java System Properties)
2021-05-11 13:21:42,072 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - application_packages: 'es.iam' (source: Java System Properties)
2021-05-11 13:21:42,072 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - log_level: 'DEBUG' (source: Java System Properties)
2021-05-11 13:21:42,072 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - log_file: 'L:/ELKIA-agent/elastic-apm-agent_18corporativos.log' (source: Java System Properties)
2021-05-11 13:21:42,072 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - No plugins dir
2021-05-11 13:21:42,103 [main] DEBUG co.elastic.apm.agent.util.DependencyInjectingServiceLoader - unable to instantiate 'co.elastic.apm.agent.httpclient.HttpClientInstrumentation', unsupported class version error: JVMCFRE003 versión mayor incorrecta; class=co/elastic/apm/agent/httpclient/HttpClientInstrumentation, offset=6
2021-05-11 13:21:42,103 [main] DEBUG co.elastic.apm.agent.util.DependencyInjectingServiceLoader - unable to instantiate 'co.elastic.apm.agent.httpclient.HttpClientAsyncInstrumentation', unsupported class version error: JVMCFRE003 versión mayor incorrecta; class=co/elastic/apm/agent/httpclient/HttpClientAsyncInstrumentation, offset=6
2021-05-11 13:21:42,103 [main] DEBUG co.elastic.apm.agent.util.DependencyInjectingServiceLoader - unable to instantiate 'co.elastic.apm.agent.httpclient.HttpRequestHeadersInstrumentation', unsupported class version error: JVMCFRE003 versión mayor incorrecta; class=co/elastic/apm/agent/httpclient/HttpRequestHeadersInstrumentation, offset=6
2021-05-11 13:21:42,167 [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@5a301f5b) has been overridden
2021-05-11 13:21:42,167 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.httpclient.ApacheHttpClientInstrumentation
2021-05-11 13:21:42,199 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.httpclient.ApacheHttpAsyncClientInstrumentation
2021-05-11 13:21:42,199 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.httpclient.ApacheHttpAsyncClientRedirectInstrumentation

and later

2021-05-11 13:21:42,261 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation ForkJoinTaskInstrumentation: (is(class java.util.concurrent.ForkJoinTask) and not(isInterface())) matches class java.util.concurrent.ForkJoinTask
2021-05-11 13:21:42,279 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation ExecutorRunnableInstrumentation: (hasSuperType(erasure(name(equals(java.util.concurrent.Executor)))) and not(name(equals(org.apache.felix.resolver.ResolverImpl$DumbExecutor))) and not(name(contains(jetty))) and not(name(contains(tomcat))) and not(name(contains(jboss))) and not(name(contains(undertow))) and not(name(contains(netty))) and not(name(startsWith(com.hazelcast))) and not((name(contains($Proxy)) or name(contains($$)) or name(contains($JaxbAccessor)) or name(contains(CGLIB)) or name(contains(EnhancerBy)))) and not(isInterface())) matches class java.util.concurrent.ForkJoinPool
2021-05-11 13:21:42,354 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation CreateSpanInstrumentation: (hasSuperType(erasure(is(class java.net.HttpURLConnection))) and not(name(equals(sun.net.www.protocol.https.HttpsURLConnectionImpl))) and not(isInterface())) matches class sun.net.www.protocol.http.HttpURLConnection

Thanks

Eyal_Koren · May 13, 2021, 11:24am

What happens later?
Do you see any interesting Method match for instrumentation ... messages as well?
What happens even later when you invoke requests on your WAS? Anything gets logged then?

fernandezsjanto · May 17, 2021, 12:26pm

The complete sequence is:

2021-05-17 14:17:28,366 [server.startup : 1] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation Init: (name(equals(init)) and hasParameter(hasTypes(with(0 matches erasure(name(equals(javax.servlet.ServletConfig)))))) and not(isAbstract())) matches public void org.apache.struts2.views.JspSupportServlet.init(javax.servlet.ServletConfig) throws javax.servlet.ServletException
2021-05-17 14:17:28,475 [server.startup : 1] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation BootstrapDelegationClassLoaderInstrumentation: (not(name(startsWith(java.))) and not(name(startsWith(jdk.))) and not(name(startsWith(com.sun.))) and not(name(startsWith(sun.))) and not(name(contains(Bootstrap))) and hasSuperType(erasure(is(class java.lang.ClassLoader))) and not(isInterface())) matches class com.opensymphony.xwork2.util.classloader.ReloadingClassLoader
2021-05-17 14:17:28,475 [server.startup : 1] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation BootstrapDelegationClassLoaderInstrumentation: (name(equals(loadClass)) and returns(erasure(is(class java.lang.Class))) and (hasParameter(hasTypes(erasures(containing(is(class java.lang.String))))) or hasParameter(hasTypes(erasures(containing(is(class java.lang.String), is(boolean)))))) and not(isAbstract())) matches public java.lang.Class com.opensymphony.xwork2.util.classloader.ReloadingClassLoader.loadClass(java.lang.String) throws java.lang.ClassNotFoundException
2021-05-17 14:17:29,157 [server.startup : 1] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation ShadingInstrumentation: (name(equals(org.apache.log4j.WriterAppender)) and not(isInterface())) matches class org.apache.log4j.WriterAppender
2021-05-17 14:17:29,157 [server.startup : 1] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation StopAppenderInstrumentation: (name(equals(org.apache.log4j.WriterAppender)) and not(isInterface())) matches class org.apache.log4j.WriterAppender
2021-05-17 14:17:29,176 [server.startup : 1] WARN  co.elastic.apm.agent.bci.bytebuddy.ErrorLoggingListener - org.apache.log4j.WriterAppender uses an unsupported class file version (pre Java 4}) and can't be instrumented. Consider updating to a newer version of that library.
2021-05-17 14:17:29,571 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Beginning scheduled configuration reload (interval is 30 sec)...
2021-05-17 14:17:29,572 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Finished scheduled configuration reload
2021-05-17 14:17:30,755 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving JSON_WRITER event (sequence 12)
2021-05-17 14:17:30,755 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://xxxxxxxs:8200/intake/v2/events
2021-05-17 14:17:30,757 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2

2021-05-17 14:19:10,784 [elastic-apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler$FlushOnTimeoutTimerTask - Request flush because the request timeout occurred
2021-05-17 14:19:10,784 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 19)
2021-05-17 14:19:10,784 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 2380 uncompressed 799 compressed bytes
2021-05-17 14:19:29,575 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Beginning scheduled configuration reload (interval is 30 sec)...
2021-05-17 14:19:29,575 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Finished scheduled configuration reload
2021-05-17 14:19:30,754 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving JSON_WRITER event (sequence 20)
2021-05-17 14:19:30,754 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://xxxxxxxx:8200/intake/v2/events
2021-05-17 14:19:30,754 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2021-05-17 14:19:40,768 [elastic-apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler$FlushOnTimeoutTimerTask - Request flush because the request timeout occurred
2021-05-17 14:19:40,768 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 21)
2021-05-17 14:19:40,768 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 2380 uncompressed 796 compressed bytes
2021-05-17 14:19:59,573 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Beginning scheduled configuration reload (interval is 30 sec)...
2021-05-17 14:19:59,573 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Finished scheduled configuration reload
2021-05-17 14:20:00,765 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving JSON_WRITER event (sequence 22)
2021-05-17 14:20:00,765 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://xxxxxxx:8200/intake/v2/events
2021-05-17 14:20:00,765 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2021-05-17 14:20:10,778 [elastic-apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler$FlushOnTimeoutTimerTask - Request flush because the request timeout occurred
2021-05-17 14:20:10,793 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 23)
2021-05-17 14:20:10,793 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 2380 uncompressed 799 compressed bytes
2021-05-17 14:20:29,574 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Beginning scheduled configuration reload (interval is 30 sec)...
2021-05-17 14:20:29,574 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Finished scheduled configuration reload
2021-05-17 14:20:30,764 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving JSON_WRITER event (sequence 24)
2021-05-17 14:20:30,764 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://xxxxxxxx:8200/intake/v2/events
2021-05-17 14:20:30,764 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2021-05-17 14:20:40,767 [elastic-apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler$FlushOnTimeoutTimerTask - Request flush because the request timeout occurred
2021-05-17 14:20:40,767 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 25)
2021-05-17 14:20:40,767 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 2379 uncompressed 793 compressed bytes
2021-05-17 14:20:59,573 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Beginning scheduled configuration reload (interval is 30 sec)...
2021-05-17 14:20:59,573 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Finished scheduled configuration reload
2021-05-17 14:21:00,763 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving JSON_WRITER event (sequence 26)
2021-05-17 14:21:00,763 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://xxxxxxxxx:8200/intake/v2/events
2021-05-17 14:21:00,763 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s

no related events appear in the websphere log

Sylvain_Juge · May 18, 2021, 8:02pm

Hi @fernandezsjanto ,

From the logs samples that you sent, we don't see what could be wrong here

If I understand correctly:

you added the Java agent version 1.23.0 using the -javaagent JVM option
the application server starts, and the application works as expected
you get some metrics visible in Kibana, but nothing else

In order to double-check, could you do the following

truncate both agent log and Websphere logs for easier debugging
keep the log_level=debug configuration
Execute a few requests against the server, the agent should capture those as transactions, for example open the WAS admin console.
inspect the logs for any error, when log_level=debug is set, you should see some captured URLs in lines that contain endTransaction

Thanks !

Side note, there appear to be a docker image for that Websphere version if required : Docker Hub

fernandezsjanto · May 19, 2021, 7:44am

Hi,
I have emptied the logs and activated the 'TRACE' level, in the agent.
The result is the same, I add some new traces:

2021-05-19 08:27:31,903 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - Starting Elastic APM 1.23.0 as 18corporativos_uweb on Java 1.8.0_261 Runtime version: 8.0.6.15 - pwa6480sr6fp15ifix-20200820_01(SR6 FP15+IJ26443) VM version: 2.9 (IBM Corporation) Windows Server 2012 R2 6.3
2021-05-19 08:27:31,903 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - service_name: '18corporativos_uweb' (source: Java System Properties)
2021-05-19 08:27:31,903 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - environment: 'DESARROLLO' (source: Java System Properties)
2021-05-19 08:27:31,903 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - server_url: 'http://XXXXXXX:8200' (source: Java System Properties)
2021-05-19 08:27:31,903 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - log_level: 'TRACE' (source: Java System Properties)
2021-05-19 08:27:31,903 [main] INFO  co.elastic.apm.agent.configuration.StartupInfo - log_file: 'L:/ELKIA-agent/elastic-apm-agent_18corporativos_uweb.log' (source: Java System Properties)
2021-05-19 08:27:31,935 [main] DEBUG co.elastic.apm.agent.util.DependencyInjectingServiceLoader - unable to instantiate 'co.elastic.apm.agent.httpclient.HttpClientInstrumentation', unsupported class version error: JVMCFRE003 versión mayor incorrecta; class=co/elastic/apm/agent/httpclient/HttpClientInstrumentation, offset=6
2021-05-19 08:27:31,935 [main] DEBUG co.elastic.apm.agent.util.DependencyInjectingServiceLoader - unable to instantiate 'co.elastic.apm.agent.httpclient.HttpClientAsyncInstrumentation', unsupported class version error: JVMCFRE003 versión mayor incorrecta; class=co/elastic/apm/agent/httpclient/HttpClientAsyncInstrumentation, offset=6
2021-05-19 08:27:31,935 [main] DEBUG co.elastic.apm.agent.util.DependencyInjectingServiceLoader - unable to instantiate 'co.elastic.apm.agent.httpclient.HttpRequestHeadersInstrumentation', unsupported class version error: JVMCFRE003 versión mayor incorrecta; class=co/elastic/apm/agent/httpclient/HttpRequestHeadersInstrumentation, offset=6
2021-05-19 08:27:31,997 [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@46f5af35) has been overridden

2021-05-19 08:27:31,997 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.httpclient.ApacheHttpClientInstrumentation
2021-05-19 08:27:32,028 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.httpclient.ApacheHttpAsyncClientInstrumentation
2021-05-19 08:27:32,028 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.httpclient.ApacheHttpAsyncClientRedirectInstrumentation
2021-05-19 08:27:32,028 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Applying instrumentation co.elastic.apm.agent.httpclient.LegacyApacheHttpClientInstrumentation

2021-05-19 08:27:32,160 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation CreateSpanInstrumentation: (hasSuperType(erasure(is(class java.net.HttpURLConnection))) and not(name(equals(sun.net.www.protocol.https.HttpsURLConnectionImpl))) and not(isInterface())) matches class sun.net.www.protocol.http.HttpURLConnection
2021-05-19 08:27:32,160 [main] TRACE co.elastic.apm.agent.bci.ElasticApmAgent - Advice co.elastic.apm.agent.urlconnection.HttpUrlConnectionInstrumentation$CreateSpanInstrumentation is loaded by null
2021-05-19 08:27:32,160 [main] TRACE co.elastic.apm.agent.bci.ElasticApmAgent - bootstrap classloader

2021-05-19 08:28:12,970 [elastic-apm-server-reporter] TRACE co.elastic.apm.agent.report.serialize.DslJsonSerializer - {"metadata":{"service":{"name":"18corporativos_uweb","environment":"DESARROLLO","agent":{"name":"java","ephemeral_id":"9e7a2f61-d365-4dd4-8af6-16f0508156d4","version":"1.23.0"},"language":{"name":"Java","version":"1.8.0_261"},"runtime":{"name":"Java","version":"1.8.0_261"},"version":null},"process":{"pid":24272,"title":"C:\\WebSphere85\\AppServer\\java_1.8_64\\jre\\bin\\java.exe"},"system":{"architecture":"amd64","hostname":"WAS8DES03","platform":"Windows Server 2012 R2"}}}
{"metricset":{"timestamp":1621405682924000,"samples":{"system.process.cpu.total.norm.pct":{"value":0.17805597939506637},"jvm.memory.heap.used":{"value":216725952.0},"jvm.memory.non_heap.used":{"value":184081948.0},"jvm.memory.heap.max":{"value":1073741824.0},"jvm.memory.non_heap.committed":{"value":573693876.0},"system.cpu.total.norm.pct":{"value":0.29368804086683475},"system.process.memory.size":{"value":744890368.0},"jvm.memory.heap.committed":{"value":280231936.0},"jvm.memory.non_heap.max":{"value":-1.0},"system.memory.actual.free":{"value":5735870464.0},"system.memory.total":{"value":42949070848.0},"jvm.thread.count":{"value":144.0}}}}
{"metricset":{"timestamp":1621405682924000,"tags":{"name":"nursery-survivor"},"samples":{"jvm.memory.heap.pool.committed":{"value":17760256.0},"jvm.memory.heap.pool.max":{"value":60420096.0},"jvm.memory.heap.pool.used":{"value":17760256.0}}}}
{"metricset":{"timestamp":1621405682924000,"tags":{"name":"nursery-allocate"},"samples":{"jvm.memory.heap.pool.committed":{"value":61145088.0},"jvm.memory.heap.pool.max":{"value":208015360.0},"jvm.memory.heap.pool.used":{"value":36492688.0}}}}
{"metricset":{"timestamp":1621405682924000,"tags":{"name":"global"},"samples":{"jvm.gc.time":{"value":393.0},"jvm.gc.count":{"value":2.0}}}}
{"metricset":{"timestamp":1621405682924000,"tags":{"name":"tenured-SOA"},"samples":{"jvm.memory.heap.pool.committed":{"value":191259648.0},"jvm.memory.heap.pool.max":{"value":956301312.0},"jvm.memory.heap.pool.used":{"value":162473008.0}}}}
{"metricset":{"timestamp":1621405682924000,"tags":{"name":"tenured-LOA"},"samples":{"jvm.memory.heap.pool.committed":{"value":10066944.0},"jvm.memory.heap.pool.max":{"value":50331648.0},"jvm.memory.heap.pool.used":{"value":0.0}}}}
{"metricset":{"timestamp":1621405682924000,"tags":{"name":"scavenge"},"samples":{"jvm.gc.time":{"value":513.0},"jvm.gc.count":{"value":35.0}}}}

The string "EndTransaction" does not appear in the log.

PS: I am using the websphere Network Deployment

Sylvain_Juge · May 19, 2021, 11:57am

@fernandezsjanto can you upload the whole log ? The string to search in log is endTransaction with a lowecase 'e' at begining.

I'm really not familiar with Websphere Network Deployment, what is the difference compared to a regular standalone setup ? Is there any kind of internal load-balancing/clustering setup ?

Elastic APM agent is only able to monitor supported frameworks, for example anything that relies on Servlets should be supported, do you know which frameworks are being used by your application to deal with HTTP requests & responses ?

Can you make HTTP requests to the specific node where you added the -javaagent option, or does it has to use the load-balancing/cluster feature ?

system · June 9, 2021, 7:57am

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