APM java agent request timeout logs

Elastic Observability APM
1

I have a question regarding the following information noted in the APM Java Agent Reference [1.x] Troubleshooting guide.

Since none of these continuously repeating DEBUG logs appear to be associated with an other WARN or ERROR level logs and resulting transactions/errors/metrics in kibana APM appear valid, would it be correct to assume that these requests timeouts are expected?

APM Java Agent Reference [1.x] | Elastic :
"After that, you should see logs indicating that the agent has successfully sent data to the APM server:

[apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
[apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 26)
[apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 10912 uncompressed 2667 compressed bytes"

2

Hi @EdeV ,

I'm not really sure to properly understand what you mean here.

If there are timeouts or connection issues when sending the data to apm-server, you will get WARN/ERROR messages.

The messages logged in DEBUG level include more details, thus it's completely expected to see such messages under normal operation of the agent.

3

Showing a typical section of repeated logs not showing intermingled WARN/ERROR logs (have removed co.elastic.apm.agent.impl.transaction.AbstractSpan and co.elastic.apm.agent.impl.ElasticApmTracer DEBUG logs here)

Looking to determine if 'Request flush because the request timeout occurred' here suggests payload send timeout failures, or are expected timed flush events?

3/30/2021 12:05:06 PM 2021-03-30 19:05:06,745 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to https://elastic-apm.xxxx.com/intake/v2/events
3/30/2021 12:05:07 PM 2021-03-30 19:05:07,456 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
3/30/2021 12:05:07 PM 2021-03-30 19:05:07,456 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102308)
3/30/2021 12:05:07 PM 2021-03-30 19:05:07,456 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102309)
3/30/2021 12:05:07 PM 2021-03-30 19:05:07,633 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102310)
3/30/2021 12:05:07 PM 2021-03-30 19:05:07,657 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102311)
3/30/2021 12:05:11 PM 2021-03-30 19:05:11,102 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Beginning scheduled configuration reload (interval is 30 sec)...
3/30/2021 12:05:11 PM 2021-03-30 19:05:11,104 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Finished scheduled configuration reload
3/30/2021 12:05:14 PM 2021-03-30 19:05:14,474 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102312)
3/30/2021 12:05:15 PM 2021-03-30 19:05:15,202 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving JSON_WRITER event (sequence 102313)
3/30/2021 12:05:17 PM 2021-03-30 19:05:17,456 [elastic-apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler$FlushOnTimeoutTimerTask - Request flush because the request timeout occurred
3/30/2021 12:05:17 PM 2021-03-30 19:05:17,462 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 102314)
3/30/2021 12:05:17 PM 2021-03-30 19:05:17,463 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 14151 uncompressed 3343 compressed bytes
3/30/2021 12:05:24 PM 2021-03-30 19:05:24,478 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102315)
3/30/2021 12:05:24 PM 2021-03-30 19:05:24,478 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to https://elastic-apm.xxxx.com/intake/v2/events
3/30/2021 12:05:24 PM 2021-03-30 19:05:24,491 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
3/30/2021 12:05:25 PM 2021-03-30 19:05:25,307 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102316)
3/30/2021 12:05:31 PM 2021-03-30 19:05:31,174 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102317)
3/30/2021 12:05:33 PM 2021-03-30 19:05:33,053 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102318)
3/30/2021 12:05:34 PM 2021-03-30 19:05:34,476 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102319)
3/30/2021 12:05:34 PM 2021-03-30 19:05:34,492 [elastic-apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler$FlushOnTimeoutTimerTask - Request flush because the request timeout occurred
3/30/2021 12:05:34 PM 2021-03-30 19:05:34,499 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 102320)
3/30/2021 12:05:34 PM 2021-03-30 19:05:34,499 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 11537 uncompressed 2627 compressed bytes
3/30/2021 12:05:41 PM 2021-03-30 19:05:41,100 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Beginning scheduled configuration reload (interval is 30 sec)...
3/30/2021 12:05:41 PM 2021-03-30 19:05:41,101 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Finished scheduled configuration reload
3/30/2021 12:05:44 PM 2021-03-30 19:05:44,479 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102321)
3/30/2021 12:05:44 PM 2021-03-30 19:05:44,479 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to https://elastic-apm.xxxx.com/intake/v2/events
3/30/2021 12:05:44 PM 2021-03-30 19:05:44,499 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
3/30/2021 12:05:45 PM 2021-03-30 19:05:45,206 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving JSON_WRITER event (sequence 102322)
3/30/2021 12:05:54 PM 2021-03-30 19:05:54,484 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102323)
3/30/2021 12:05:54 PM 2021-03-30 19:05:54,499 [elastic-apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler$FlushOnTimeoutTimerTask - Request flush because the request timeout occurred
3/30/2021 12:05:54 PM 2021-03-30 19:05:54,507 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 102324)
3/30/2021 12:05:54 PM 2021-03-30 19:05:54,508 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 5485 uncompressed 1785 compressed bytes
3/30/2021 12:05:55 PM 2021-03-30 19:05:55,383 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102325)
3/30/2021 12:05:55 PM 2021-03-30 19:05:55,383 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to https://elastic-apm.xxxx.com/intake/v2/events
3/30/2021 12:05:55 PM 2021-03-30 19:05:55,384 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
3/30/2021 12:06:01 PM 2021-03-30 19:06:01,353 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102326)
3/30/2021 12:06:04 PM 2021-03-30 19:06:04,496 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102327)
3/30/2021 12:06:05 PM 2021-03-30 19:06:05,384 [elastic-apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler$FlushOnTimeoutTimerTask - Request flush because the request timeout occurred
3/30/2021 12:06:05 PM 2021-03-30 19:06:05,392 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 102328)
3/30/2021 12:06:05 PM 2021-03-30 19:06:05,392 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 7515 uncompressed 2349 compressed bytes
3/30/2021 12:06:11 PM 2021-03-30 19:06:11,100 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Beginning scheduled configuration reload (interval is 30 sec)...
3/30/2021 12:06:11 PM 2021-03-30 19:06:11,101 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Finished scheduled configuration reload
3/30/2021 12:06:14 PM 2021-03-30 19:06:14,474 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102329)
3/30/2021 12:06:14 PM 2021-03-30 19:06:14,474 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to https://elastic-apm.xxxx.com/intake/v2/events
3/30/2021 12:06:14 PM 2021-03-30 19:06:14,482 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
3/30/2021 12:06:15 PM 2021-03-30 19:06:15,200 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving JSON_WRITER event (sequence 102330)
3/30/2021 12:06:24 PM 2021-03-30 19:06:24,477 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 102331)
3/30/2021 12:06:24 PM 2021-03-30 19:06:24,483 [elastic-apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler$FlushOnTimeoutTimerTask - Request flush because the request timeout occurred
3/30/2021 12:06:24 PM 2021-03-30 19:06:24,483 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 102332)
3/30/2021 12:06:24 PM 2021-03-30 19:06:24,484 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 5487 uncompressed 1791 compressed bytes
4

Hi @EdeV,

The Request flush because the request timeout occurred message is not related to connection timeout, it just means that the delay before flushing has been reached and agent has to send data to server.

If there was any network error, it would have been logged in WARN or ERROR so you'll get notified with the default log_level value.

5

Thank you @Sylvain_Juge for the clarification.

6

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