Transaction not automatically propagated from browser to backend

[maxant (Ant Kutschera)]

I have added the javascript agent to a test application as described in the docs:

<script src="https://unpkg.com/@elastic/apm-rum@4.0.1/dist/bundles/elastic-apm-rum.umd.min.js"></script>
<script>
    // set up tracing (elastic apm) - see https://www.elastic.co/guide/en/apm/agent/js-base/current/api.html
    // TODO find a better place for apm object to live
    window.elasticapm = elasticApm.init({
      serviceName: 'ui',
      //serverUrl: 'http://localhost:30200/proxy',
      serverUrl: 'http://maxant.ch:30200',
      serviceVersion: 'beta',
      logLevel: 'trace',
      environment: 'test'
    });
    window.elasticapm.setUserContext({id: "UserNumber", username: "ant", email: "someaddress@maxant.ch"});
</script>

I've then added the calls to the API in the "controller" of my single page app:

 async createClaim(claim) {
    const tracingTransaction = window.elasticapm.startTransaction("createClaim", "ui-tx");
     try {
         await service.createClaim(claim, model.partner.entity.id);
     } catch (error) {
         window.elasticapm.captureError(error);
         model.claims.error = error;
    } finally {
        tracingTransaction.end();
    }
}

The tracing is visible in Kibana, but it doesn't show it as a transaction which is related to further downstream calls. No transaction ID or trace ID is sent from the browser to the backend, so the backend starts a new transaction.

Should the propagation occur automatically, or do I have to do something special? The Javascript object called "service" above, uses the axios library and does this:

function createClaim(form, partnerId) {
  return new Promise(function (resolve, reject) {
    setTimeout(function(){ // so that demo shows "in progress" message
        const claim = {"summary": form.summary, "description": form.description, "partnerId": partnerId, "reserve": form.reserve, "date": form.date.replace(/\//g, "-")};
        axios.post(CLAIMS_BASE_URL + 'claims', claim)
        .then(function(response) {
            if(response.status === 202) {
                console.log("claim creation request accepted");
                resolve();
            } else reject("Unexpected response code " + response.status);
        }).catch(function(call) {
            console.error("Failed to create claim: " + JSON.stringify(call));
            reject("Failed to create claim. See console for details. (" + (call.response?call.response.status:"-") + ")");
        });
    }, 1000);
  });
}

Maybe axios needs to be setup somehow? Altho under the hood it should be using XMLHTTPRequest.

Calls to the events UI are successful. there are no http errors anywhere.

Chrome logs the request which axios makes to the backend as only having these headers:

1. Accept: application/json, text/plain, /
2. Origin: http://localhost:8083
3. Referer: http://localhost:8083/
4. User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.75 Safari/537.36

As you can see, there is none with a transaction ID. Backend-to-Backend contains headers like the following to propagate the transaction:

Elastic-Apm-Traceparent	
[
    "00-62f406aea109c9f76ddcd800f6548a51-ec5a373da6a5d2c0-01"
]

I tried adding the current trace ID to the headers which are sent to the backend, but I still don't see the backend calls as part of the UI transaction when I look at it in kibana apm:

        axios.post(CLAIMS_BASE_URL + 'claims', claim, {headers: {"Elastic-Apm-Traceparent": elasticApm.getCurrentTransaction().traceId}})
        .then(function(response) {

I noticed that the traceId returned from "getCurrentTransaction" is really short, compared to the example show above from backend-to-backend, e.g. 5f8684e59724df24309ae961395e65b3

I also noticed that the ID returned from getCurrentTransaction().traceId is not the same as the one created when I called elasticapm.startTransaction("createClaim", "ui-tx"); I've tried sending both IDs to the backend, but the timeline of the UI never shows the backend call as part of the transaction.

Is it possible to see a timeline with the UI, and all backends together?

Kibana version:

7.0.0

Elasticsearch version:

7.0.0

APM Server version:

7.0.0

APM Agent language and version:

javascript 4.0.1

Browser version:

chrome 73

Original install method (e.g. download page, yum, deb, from source, etc.) and version:

docker images running in minikube

Fresh install or upgraded from other version?

fresh

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.

ES output
no loadbalancers
no index patterns changed
no custom templates

Errors in browser console (if relevant):

none

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

[Hamidreza (Hamidreza Jahtalabziabari)]

Hi,

Thanks for using Elastic APM and welcome to the forum.

The RUM agent by default only adds the elastic-apm-traceparent header to requests made to the same origin as the page, but if you're making cross-origin requests that you want to monitor, then you should configure distributedTracingOrigins option so that the elastic-apm-traceparent header is added to those requests as well. You can find more info about this config option and the reasoning behind the default behaviour in our guide on distributed tracing.

As a side note, you don't need to assign window.elasticapm, simply using elasticApm should work.

Let me know if you have more questions

Cheers,
Hamid

[maxant (Ant Kutschera)]

@Hamidreza

distributedTracingOrigins

Thanks @Hamidreza , that helps.

I added:

distributedTracingOrigins: ['https://kdc.maxant.ch','http://localhost:8083','http://localhost:8081']

The header is now sent automatically and is a lot longer and more similar to the backend-to-backend headers, e.g.:

elastic-apm-traceparent: 00-6ef709f1f91baa218d731a7aca056276-b03aba0339fa2385-01

If I now look at the ui service in the APM browser, and click on the createClaim transaction, it looks like this:

1. that hasn't changed from yesterday (I'm looking at the latest transaction instance though - see the date/time)
2. I assumed it would include child transactions / spans because the call chain is actually like this: web -> POST localhost:8083/claims -> an EJB -> POST localhost:8082/tasks
3. the GET http://localhost:8082/tasks shown in the picture above is a) unrelated to the transaction started before POSTing to localhost:8083/claims and b) localhost:8082 is NOT in the list of distributedTracingOrigins

If however I view the claims service (the first backend service called from the UI), and look at the latest transaction, it looks like this:

That shows the call from the claims service to the tasks service. Strangely It shows three HTTP calls each of microsecond length - I don't quite understand that.

It shows that the backend call is 76.9% of the trace, so it seems to know that something is missing. But why doesn't it show it automatically? If I click the "view full trace" button, it jumps to the UI trace, but as shown above, it doesn't show the backend stuff.

I expected to be able to view the entire call chain somewhere - is that possible?

Perhaps it is because all the servers have different hostnames? In the target environment they will have proper hostnames (rather than localhost), but still different, e.g.: "claims.maxant.ch", "tasks.maxant.ch", "ui.maxant.ch", etc.

Also, is it correct that the user information isn't propagated automatically? That makes sense to me, as I would probably use JWT or similar in a real scenario.

You can have a look at the APM browser yourself if it helps - it is just a lab environment:

• 404 | Not Found

• 404 | Not Found

[Hamidreza (Hamidreza Jahtalabziabari)]

Hi,

Thanks for the detailed explanation of the problem.

The GET http://localhost:8082/tasks span is captured since it happens after the call to startTransaction which sets the "current transaction". The RUM agent automatically captures these as a part of the current transaction. This is unrelated to distributedTracingOrigins config option which only tells the agent which requests to add the elastic-apm-traceparent header to.

The reason that the POST request is not included in the transaction is the setTimeout(..., 1000) that is used to delay the actual request. Currently we don't capture setTimeout calls, I've created an issue to provide that.

In the meantime, there are some work arounds for this. You can start the transaction just before you make the POST request.

Or You can use our experimental task API:

async function createClaim(claim) {
    const tracingTransaction = window.elasticapm.startTransaction("createClaim", "ui-tx");
    tracingTransaction.addTask()
    try {
        await service.createClaim(claim, model.partner.entity.id);
    } catch (error) {
        window.elasticapm.captureError(error);
        model.claims.error = error;
    } finally {
        tracingTransaction.end();
    }
}

Using the addTask API would essentially prevent the agent from automatically detecting the transaction end until either the task is removed or Transaction.end() is called. Please note that this API is still experimental and might change in the future. Feedback is much appreciated though

Cheers,
Hamid

[maxant (Ant Kutschera)]

@Hamidreza

addTask()

Thanks @Hamidreza

I removed the setTimeout prior to the tests that I did before posting my last post. But your idea gave me some inspiration. In this simple example, the user's click leads to a single backend call. In a more real example, it might lead to a number of microservice calls, and we'd want to track each one within the transaction. So I added a span, and hey presto, I get everything traced as I want!

A click leads to a call to the controller, which starts the transaction:

loadClaims() {
    const tracingTransaction = elasticApm.startTransaction("loadClaims", "ui-tx");
    service.loadClaims().subscribe(
        response => {
            model.claims.entities$.next(response.data);
            tracingTransaction.end();
        },
        error => {
            elasticApm.captureError(error);
            tracingTransaction.end(); // necessary in addition to capureError, see https://www.elastic.co/guide/en/apm/agent/js-base/current/custom-transactions.html
            model.claims.entities$.next([]);
        }
    );
}

The service contains the span (I'm not 100% sure if I need to close the span if there is an error, the rejected promise is handled above, where I call captureError):

function createClaim(form, partnerId) {
    var url = CLAIMS_BASE_URL + 'claims';
    var span = elasticApm.getCurrentTransaction().startSpan('POST' + url, 'http')
    return new Promise(function (resolve, reject) {
        const claim = {"summary": form.summary,...
        axios.post(url, claim)
        .then(function(response) {
            span.end()
            if(response.status === 202) {
                resolve();
            } else reject("Unexpected response code " + response.status);
        }).catch(function(call) {
            console.error("Failed to create claim: " + JSON.stringify(call));
            reject("Failed to create claim. See console for details.");
        });
    });
}

Thanks!