Kibana APM not showing @CaptureSpan and @CaptureTransaction

Elastic Observability APM
1

Kibana version 6.5.3:

Elasticsearch version 6.5.3:

APM Server version 1.4.0:

APM Agent language and version 1.4.0 for Java & Tomcat:

We installed an APM server and Agent for our java app on Tomcat.

We added this to our tomcat/bin.catalina.sh on Debian Linux

JAVA_OPTS="-DTOMCAT5 -verbosegc -Xms2G -Xmx8G -noverify -DQES_DIR=$SOFTWARE/conf -Dfile.encoding=UTF-8 -Dlog4j.configuration=file://$SOFTWARE/conf/log4j.properties -Dorg.xml.sax.driver=org.apache.xerces.parsers.SAXParser -Dorg.owasp.esapi.resources=$SOFTWARE/conf -Dlog4j.configurationFile=file://$SOFTWARE/conf/log4j.properties -javaagent:/usr/software/apm-client/elastic-apm-agent-1.4.0.jar -Delastic.apm.service_name=qeswebmonitor -Delastic.apm.server_url=http://localhost:8200 -Delastic.apm.application_packages=com.qwam  "

We added the needed maven jars to our app.
We added some annotations such as this one on a couple of methods

package com.qwam.qesrest.facet.services

import co.elastic.apm.api.CaptureSpan
import com.qwam.qes.QESChamp
import com.qwam.qes.QESListe_valeur
import com.qwam.qes.QESObject
import com.qwam.qes.QESSession
import com.qwam.qes.QESUtilisateur
import com.qwam.qesrest.core.domain.Constants
import com.qwam.qesrest.facet.domain.Facet
import com.qwam.qesrest.facet.domain.FacetValue

import java.sql.Connection

public class FacetService extends QESObject {



FacetService() {
}

@CaptureSpan("xmlToFacets")
public List xmlToFacets(QESSession ses, Connection connection, QESUtilisateur utilisateur, Hashtable<String,String> facetTranslations, String xml) {

    List facets = []

    println('DEBUG:FacetService:xmlToFacets():Debut')

....
}

We can see our requests along with the SQL statement executions in the APM kibana dashboard but

  • No trace for @CaptureSpan and @CaptureTransaction, despite we check that the TRACE is in deed in the logs (which says that the method was executed)
  • Could not find it in discover (as far as we could see)

The option

-Delastic.apm.application_packages=com.qwam

was mentioned in the doc for @CaptureSpan and @CaptureTransaction.
Should we declare every package such as

-Delastic.apm.application_packages=com.qwam.subpackage1,com.qwam.subpackage2

or

-Delastic.apm.application_packages=com.qwam

is enough ?

Looks like an issue from a Noob, but could not find a solution on my own.

2

Hi and thanks for trying out our APM :slight_smile:

Your root package setting seems OK, no need for sub-packages.

Note that if you capture a Span while there is no active transaction, this span will not be sent and stored. So you should verify that for each request, the first event is traced through CaptureTransaction and all subsequent events are captured through CaptureSpan. From the code you added, I can't see if this is indeed related to the problem or not.
For more info see our data model documentation.

I hope this helps. If not, please set log level to TRACE and upload the log.

Thanks,
Eyal.

3

Hi Eyal,

I added @CaptureTransaction atop my main service: Nothing much appears

Added -Delastic.apm.log_level=TRACE to my JAVA_OPTS

Here are the logs

As you can see there are only Spans for JDBC in there.

4

Thanks for the logs.

I do see FacetService#xmlToFacets occurs within a traced transaction (QESResultat_jsp#doGet) and not being traced. Your settings look fine, so I can't see what's wrong at the moment. Please upload the startup area of this log, where we log the active instrumentations and matchings, maybe we can find some hints there.

Thanks,
Eyal.

5

Here are the

Full logs

Sorry for lengthy logs since I am not alone on this Tomcat instance.

6

Looks like the agent doesn't find any type and method match to the CaptureSpanInstrumentation although it sees the application_packages properly set to com.qwam.
Please add the following code to the FacetService constructor, so we can see which class loader loads it:

        ClassLoader classLoader = getClass().getClassLoader();
        while (classLoader != null) {
            System.out.println(classLoader.getClass().getName());
            classLoader = classLoader.getParent();
        }
7

@ivanqwam and if you are already adding, please also add to the same constructor:

System.out.println("CaptureSpan class loader: " + CaptureSpan.class.getClassLoader());
8

I modified my code as requested.

Here is my code

package com.qwam.qesrest.facet.services

import co.elastic.apm.api.CaptureSpan
import com.qwam.qes.QESChamp
import com.qwam.qes.QESListe_valeur
import com.qwam.qes.QESObject
import com.qwam.qes.QESSession
import com.qwam.qes.QESUtilisateur
import com.qwam.qesrest.core.domain.Constants
import com.qwam.qesrest.facet.domain.Facet
import com.qwam.qesrest.facet.domain.FacetValue

import java.sql.Connection

public class FacetService extends QESObject {



    FacetService() {
    }

    @CaptureSpan
    public List xmlToFacets(QESSession ses, Connection connection, QESUtilisateur utilisateur, Hashtable<String,String> facetTranslations, String xml) {

        List facets = []

        println('DEBUG:FacetService:xmlToFacets():Debut')
        
        // debug Eyal Elastic
        System.out.println('DEBUG:Eyal:CaptureSpan class loader: ' + CaptureSpan.class.getClassLoader());
        ClassLoader classLoader = getClass().getClassLoader();
        while (classLoader != null) {
            System.out.println('DEBUG:Eyal:class loaded by:' + classLoader.getClass().getName());
            classLoader = classLoader.getParent();
        }

which gives this traces

2019/03/20 14:33:53 998-qeswebmonitor-demoqwam-TRACE-ResultatService-buildFacetJstl() : Debut|
DEBUG:FacetService:xmlToFacets():Debut
DEBUG:Eyal:CaptureSpan class loader: ParallelWebappClassLoader^M
  context: qeswebmonitor^M
  delegate: false^M
----------> Parent Classloader:^M
java.net.URLClassLoader@617c74e5^M

    DEBUG:Eyal:class loaded by:org.apache.catalina.loader.ParallelWebappClassLoader
    DEBUG:Eyal:class loaded by:java.net.URLClassLoader
    DEBUG:Eyal:class loaded by:sun.misc.Launcher$AppClassLoader
    DEBUG:Eyal:class loaded by:sun.misc.Launcher$ExtClassLoader
    DEBUG:FacetService:xmlToFacets():Fin

Trying to guess where you were going I added the apm-agent-api-1.4.0.jar to Tomcat lib (it is currently in myapp/WEB-INF/lib) thinking that Tomcat should now the jar before the app, since APM is outside the app. But this does not change anything

9

The WEB-INF/lib should work just fine. Anyway, it seems it loaded the class from there even after you added to tomcat lib (which makes sense because the ParallelWebappClassLoader has the delegate: false setting, so it searches locally first). Did you add any other jar to WEB-INF/lib?

10

I added only apm-agent-api-1.4.0.jar in WEB-INF/lib.
I had an issue with netty.jar* that I had to add in $CATALINA_HOME/lib to avoid a strange NoClassDefFound despite they were in WEB-INF/lib.
That is all.

11

I had an issue with netty .jar * that I had to add in $CATALINA_HOME/lib to avoid a strange NoClassDefFound despite they were in WEB-INF/lib .

This may be important - you mean you had this problem when you installed the agent? If so, can you reproduce and send this log?

12

Good morning Eyal,

I could not reproduce the NoClassDefFound about netty jars that I had in the install.
But when I remove the netty jars from $CATALINA_HOME/lib, only relying on those which are in the WEB-INF/lib, I get JSP page error from Tomcat and nothing works anymore.
Here is the netty jar list:

netty-buffer-4.1.16.Final.jar
netty-codec-4.1.16.Final.jar
netty-codec-http-4.1.16.Final.jar
netty-common-4.1.16.Final.jar
netty-handler-4.1.16.Final.jar
netty-resolver-4.1.16.Final.jar
netty-transport-4.1.16.Final.jar
transport-netty4-client-6.2.1.jar

This dependency upon netty is strange because the Maven dependency for APM does not say a word about it.

There is not much explanations in the logs when the JSP page error from Tomcat occurs.

13

Well, I can't say at the moment if this is related or not to the tracing failure you originally reported, but this is really bad. Normally you should just be able to add the API jar to your application and the java agent jar to your JVM startup and nothing else.

This log indeed says nothing related. If possible, please remove the elastic.apm.log_level setting (to restore to INFO level) and restore everything to the original state- your application and Tomcat original setup, Elastic API jar in the app lib and the javaagent in the JVM setup. Then clean the logs, start the app, make a few requests and upload the full log.

Thanks,
Eyal.

14

@ivanqwam please paste here the maven dependency you added in order to use our API

15

Eyal, please forget my last.
The Error 404 came from a developper who performed a buggy commit.
You were so fast to respond, that I did not have time to cancel my post.
We apologize for this Eyal.

I came back to the situation where the netty jar are removed from $CATALINA_HOME/lib with a fresh restart. I could not reproduce the NoCLassDefFound issue I had on netty during the install.

Here are the full logs

My maven dependencies came from here

<dependency>
<groupId>co.elastic.apm</groupId>
<artifactId>apm-agent-api</artifactId>
<version>1.4.0</version>
</dependency>

which leads to this list

apm-agent-api-1.4.0.jar 
backport-util-concurrent-3.1.jar 
classworlds-1.1-alpha-2.jar 
classworlds-1.1.jar 
commons-cli-1.0.jar 
commons-codec-1.6.jar 
commons-lang-2.1.jar 
commons-lang3-3.1.jar 
commons-logging-api-1.1.jar 
doxia-sink-api-1.0-alpha-7.jar 
google-collections-1.0.jar 
jsr305-2.0.1.jar 
junit-3.8.1.jar 
junit-3.8.2.jar 
log4j-1.2.12.jar 
surefire-api-2.17.jar 
surefire-booter-2.17.jar 
xbean-reflect-3.4.jar

I will have to switch to something else in the next few days, so I won't be available.
I will be back in a week or so.

Do not worry if you did not solve my issue, I know it will work sooner or later.
APM is a great tool and we have already seen so many things and so many hints to improve performances of our app, even without the annotation working that, it showed us how wonderful and easy to set up it can be.

Thank you Eyal for your tenacious help.

1 Like
16

Thanks for the incredible feedback! It is great to know that you found it valuable!
Once you're back and available for that, we can start fresh and take it from there.
Cheers,
Eyal.

17

Hi Eyal,

I am back.

Trying to narrow down the issue, I installed everything on my desktop.
I have a Tomcat 9.0.5 there and for sure I am alone.

But I cannot get my application deployed on Tomcat.
Instead, I get and in the logs

Caused by: java.lang.LinkageError: loader (instance of org/apache/catalina/loader/ParallelWebappClassLoader): attempted duplicate class definition for name: "javax/ws/rs/Path"

18

Welcome back :slight_smile:

Doesn't seem related to the agent. You may have the JAX-RS jar more than once on your application's classpath, for example - both in the tomcat/lib and the WEB-INF/lib.

Does it work when the agent is not installed?

19

javax/ws/rs/Path

was both in

  • jersey-core-1.9.jar
  • javax.annotation-api-1.2.jar

I removed javax.annotation-api-1.2.jar
I checked $CATALINA_HOME/lib , no such class there.
I restarted with the same result.

When restarting Tomcat without

-javaagent:/usr/software/apm-client/elastic-apm-agent-1.4.0.jar -Delastic.apm.service_name=qeswebmonitor -Delastic.apm.server_url=http://localhost:8200 -Delastic.apm.application_packages=com.qwam

in the JAVA_OPTS, the application is deployed normally without this issue.

I agree that it does not seem related to APM, but since it works without it, I lazily turn to you :flushed:.

20

Ahh, I see why we can cause that...
Can you set jax-rs in the instrumentation diablement configuration and see if the problem disappears? It's just a check, you seem to need this instrumentation, so I will create a fix once it is verified.

Still, I assume there is another jar with this class somewhere (maybe in jre-home/lib/ext?), so if you find such and can remove it, it may resolve the problem