APM java agent not capturing background process

[Ilham_Sulaksono]

Kibana version: 7.13.3

Elasticsearch version: 7.13.3

APM Server version: 7.13.3

APM Agent language and version: Java 1.25.0

Browser version: Chrome Version 93.0.4577.63

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

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): We are using spring quartz as a scheduler. But somehow we are unable to get background span/transaction for this quartz. I know from ES APM documentation that by default ES APM should be able to trace background task/process such as spring quartz. But somehow we are not getting any. And, when we try to search on apm logs, we only able to get "request" and "messaging" type.

Is this expected? If not, any idea how to trace background tasks?

[Sylvain_Juge]

Hi @Ilham_Sulaksono , welcome to the forum !

We do have support for Quartz scheduled tasks, can you tell us a bit more about the following:

• What are the version of your dependencies for quartz, spring and spring-quartz ?
• How do you define your jobs ? code (or pseudo-code) samples might help here.
• Can you capture the agent debug logs using the following procedure ?

Capturing agent debug logs

Ideally this should be done outside of production:

• it requires to restart the application
• debug logs can be verbose
• ideally having only a few transactions in the log help for investigation as there is less noise due to production traffic
• if not possible, we can still use it for a few minutes in production, when using an external configuration file (doc) the log_level can be changed at runtime.

Here, we will refer to the agent log file as /tmp/agent.log, but any other location could be used.

1. configure the agent with log_level=debug (doc) and log_file=/tmp/agent.log (doc)
2. truncate the /tmp/agent.log file and restart the application
3. execute a few transactions which aren't properly captured by the agent
4. copy the /tmp/agent.log file and send it back for investigation

[Ilham_Sulaksono]

Hi Sylvain,
Looks like agent able to trace background job because we can see the job name in the apm agent debug log. But I'm not sure why we can't see it in Kibana

Here is the log from apm agent

{"@timestamp":"2021-09-16T08:56:09.673Z", "log.level":"DEBUG", "message":"increment references to 'DEFAULT.revokeAuthorizationCodeJobDetail' 00-9ad7d6113718f1d2e651efeaeb6d1daf-678700d2f355f8c9-01 (63e9955a) (3)", "ecs.version": "1.2.0","event.dataset":"scheduler.apm","process.thread.name":"quartzScheduler_Worker-5","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}
{"@timestamp":"2021-09-16T08:56:09.673Z", "log.level":"DEBUG", "message":"increment references to '' 00-9ad7d6113718f1d2e651efeaeb6d1daf-202d4d433270b29d-01 (1e0ca4e8) (1)", "ecs.version": "1.2.0","event.dataset":"scheduler.apm","process.thread.name":"quartzScheduler_Worker-5","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}
{"@timestamp":"2021-09-16T08:56:09.673Z", "log.level":"DEBUG", "message":"increment references to 'DEFAULT.revokeAuthorizationCodeJobDetail' 00-9ad7d6113718f1d2e651efeaeb6d1daf-678700d2f355f8c9-01 (63e9955a) (4)", "ecs.version": "1.2.0","event.dataset":"scheduler.apm","process.thread.name":"quartzScheduler_Worker-5","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}
{"@timestamp":"2021-09-16T08:56:09.673Z", "log.level":"DEBUG", "message":"Activating '' 00-9ad7d6113718f1d2e651efeaeb6d1daf-202d4d433270b29d-01 (1e0ca4e8) on thread 47", "ecs.version": "1.2.0","event.dataset":"scheduler.apm","process.thread.name":"quartzScheduler_Worker-5","log.logger":"co.elastic.apm.agent.impl.ElasticApmTracer"}
{"@timestamp":"2021-09-16T08:56:09.673Z", "log.level":"DEBUG", "message":"increment references to 'DEFAULT.revokeAuthorizationCodeJobDetail' 00-9ad7d6113718f1d2e651efeaeb6d1daf-678700d2f355f8c9-01 (63e9955a) (5)", "ecs.version": "1.2.0","event.dataset":"scheduler.apm","process.thread.name":"quartzScheduler_Worker-5","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}
{"@timestamp":"2021-09-16T08:56:09.673Z", "log.level":"DEBUG", "message":"increment references to '' 00-9ad7d6113718f1d2e651efeaeb6d1daf-202d4d433270b29d-01 (1e0ca4e8) (2)", "ecs.version": "1.2.0","event.dataset":"scheduler.apm","process.thread.name":"quartzScheduler_Worker-5","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}
{"@timestamp":"2021-09-16T08:56:09.673Z", "log.level":"DEBUG", "message":"Deactivating 'RabbitMQ SEND to revoke-authorization-code-scheduler' 00-9ad7d6113718f1d2e651efeaeb6d1daf-202d4d433270b29d-01 (1e0ca4e8) on thread 47", "ecs.version": "1.2.0","event.dataset":"scheduler.apm","process.thread.name":"quartzScheduler_Worker-5","log.logger":"co.elastic.apm.agent.impl.ElasticApmTracer"}
{"@timestamp":"2021-09-16T08:56:09.673Z", "log.level":"DEBUG", "message":"decrement references to 'DEFAULT.revokeAuthorizationCodeJobDetail' 00-9ad7d6113718f1d2e651efeaeb6d1daf-678700d2f355f8c9-01 (63e9955a) (4)", "ecs.version": "1.2.0","event.dataset":"scheduler.apm","process.thread.name":"quartzScheduler_Worker-5","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}
{"@timestamp":"2021-09-16T08:56:09.674Z", "log.level":"DEBUG", "message":"decrement references to 'RabbitMQ SEND to revoke-authorization-code-scheduler' 00-9ad7d6113718f1d2e651efeaeb6d1daf-202d4d433270b29d-01 (1e0ca4e8) (1)", "ecs.version": "1.2.0","event.dataset":"scheduler.apm","process.thread.name":"quartzScheduler_Worker-5","log.logger":"co.elastic.apm.agent.impl.transaction.AbstractSpan"}
{"@timestamp":"2021-09-16T08:56:09.674Z", "log.level":"DEBUG", "message":"endSpan 'RabbitMQ SEND to revoke-authorization-code-scheduler' 00-9ad7d6113718f1d2e651efeaeb6d1daf-202d4d433270b29d-01 (1e0ca4e8)", "ecs.version": "1.2.0","event.dataset":"scheduler.apm","process.thread.name":"quartzScheduler_Worker-5","log.logger":"co.elastic.apm.agent.impl.transaction.Span"}

[Eyal_Koren]

Can you find log events starting with endTransaction ... for Quartz-related transactions?
If not, please provide a full debug log, not too long (meaning - from startup and until after a couple of jobs are fully executed) so we can see why. You can share such through gist.
If you do find such log events, try to capture log with trace level for a short period. In this level, the agent would print all documents sent to APM Server, so we can see whether such transactions are sent.

[Ilham_Sulaksono]

@Eyal_Koren

gist

Hi Eyal,
We are able to see some "endTransaction .." log for our quartz-related transaction. But I'm a bit confuse on how to read request to APM server. Could you tell us more about this?

Here is our apm agent log https://gist.github.com/ilham9649-gdplabs/5900971061b120d9bd1705174711affb
and you can find our quartz related transaction with filter "endTransaction 'DEFAULT.candidateProposedScheduleJobDetail'".
Thanks

[Sylvain_Juge]

Hi @Ilham_Sulaksono ,

Since the log here is in ECS format, making it human-readeable requires a bit of work:

• first identify which transaction names we are interested in: for example DEFAULT.webhookJobDetail
• grep for the log in lines that contain with TRACE and DEFAULT.webhookJobDetail
• extract the escaped ND-JSON string in message property

When doing that, we find that the following data has been sent for the transaction.

• you should be able to search related document with the transaction_id or trace_id fields
• you should be able to see transaction in Kibana, just make sure to select scheduled as transaction type, I think the default only shows request type, thus they may be filtered-out.

{"transaction":{"timestamp":1632706920139003,"name":"DEFAULT.webhookJobDetail","id":"a918fc687f52dd96","trace_id":"d415719eb40b8500e32fbe904ea37cc6","type":"scheduled","duration":6760.929,"outcome":"success","context":{"service":{"framework":{"version":"2.3.1","name":"Quartz"},"name":null},"tags":{}},"span_count":{"dropped":0,"started":13},"sample_rate":0.5,"sampled":true}}

[Ilham_Sulaksono]

Hi Sylvain,
After troubleshooting the issue, we need to add "elastic.apm.application_packages" while executing jar file to get scheduled transaction. And inside Kibana UI, we need to change transaction type to "scheduled"