No transaction data in APM

Elastic Observability APM
1

Kibana version: 7.5.1

Elasticsearch version: 7.5.1

APM Server version: 7.5.0

APM Agent language and version: java, 1.12

Browser version: Chrome 79, Windows 10

Original install method (e.g. download page, yum, deb, from source, etc.) and version: Downloaded from maven, attached to Tomcat by setting JAVA_OPTS

Fresh install or upgraded from other version?: Fresh install

Is there anything special in your setup? I don't have access to the APM Server, but I think the index pattern was changed to just apm-{version}, plus ILM rollover.

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant): The four services in the screenshot below all use the same tech stack (Open JDK 8, Tomcat 7 / Spring WebMVC 3.2), but two of them show no data in APM (except for the service name and JVMs), even though there is actual HTTP activity ongoing. I've run out of things to try.

image
image1504×257 24.9 KB

image
image1815×894 41.2 KB

Errors in browser console (if relevant): None

Provide logs and/or server output (if relevant): Nothing strange appears in the APM Java agent logs. Occasionally, there's the 503 - Queue full message, but this happens with all services, including the ones with transaction data. When i enable debug logs, I don't see any TRANSACTION events, only METRICS and FLUSH. I don't have access to the server logs, but everything else seems OK.

2

Could you provide debug logs from one service which works and one which does not?

Note that we don't officially support and thus not test Spring MVC 3. But if the servlet container supports Servlet API 3.0+ there should at least be basic information available.

3

From a service that isn't working:

2020-02-04 19:00:14.070 [apm-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Error sending data to APM server: Server returned HTTP response code: 503 for URL: http://172.24.102.69:8200/intake/v2/events, response code is 503
2020-02-04 19:00:14.070 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Sending payload to APM server failed
java.io.IOException: Server returned HTTP response code: 503 for URL: http://172.24.102.69:8200/intake/v2/events
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1840)
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1441)
        at co.elastic.apm.agent.report.IntakeV2ReportingEventHandler.flush(IntakeV2ReportingEventHandler.java:224)
        at co.elastic.apm.agent.report.IntakeV2ReportingEventHandler.handleEvent(IntakeV2ReportingEventHandler.java:128)
        at co.elastic.apm.agent.report.IntakeV2ReportingEventHandler.onEvent(IntakeV2ReportingEventHandler.java:116)
        at co.elastic.apm.agent.report.IntakeV2ReportingEventHandler.onEvent(IntakeV2ReportingEventHandler.java:50)
        at co.elastic.apm.agent.shaded.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:168)
        at co.elastic.apm.agent.shaded.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125)
        at java.lang.Thread.run(Thread.java:745)
2020-02-04 19:00:14.071 [apm-reporter] WARN co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - {
  "accepted": 0,
  "errors": [
    {
      "message": "queue is full"
    }
  ]
}
2020-02-04 19:00:32.696 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 30s
2020-02-04 19:00:33.057 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 6176)
2020-02-04 19:00:33.057 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://172.24.102.69:8200/intake/v2/events
2020-02-04 19:00:33.060 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2020-02-04 19:00:43.060 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2020-02-04 19:00:43.068 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 6177)
2020-02-04 19:00:43.069 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1445 uncompressed 631 compressed bytes
2020-02-04 19:01:02.696 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server http://172.24.102.69:8200/config/v1/agents
2020-02-04 19:01:03.057 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 6178)
2020-02-04 19:01:03.057 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://172.24.102.69:8200/intake/v2/events
2020-02-04 19:01:03.058 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2020-02-04 19:01:06.570 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Configuration did not change
2020-02-04 19:01:06.571 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 30s
2020-02-04 19:01:13.058 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2020-02-04 19:01:13.058 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 6179)
2020-02-04 19:01:13.059 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1445 uncompressed 633 compressed bytes
2020-02-04 19:01:33.060 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 6180)
2020-02-04 19:01:33.060 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://172.24.102.69:8200/intake/v2/events
2020-02-04 19:01:33.062 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2020-02-04 19:01:36.571 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server http://172.24.102.69:8200/config/v1/agents
2020-02-04 19:01:39.209 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Configuration did not change
2020-02-04 19:01:39.209 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 30s
2020-02-04 19:01:43.063 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2020-02-04 19:01:43.067 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 6181)
2020-02-04 19:01:43.067 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1443 uncompressed 631 compressed bytes
2020-02-04 19:02:03.057 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 6182)
2020-02-04 19:02:03.057 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://172.24.102.69:8200/intake/v2/events
2020-02-04 19:02:03.058 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2020-02-04 19:02:09.209 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server http://172.24.102.69:8200/config/v1/agents
2020-02-04 19:02:11.254 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Configuration did not change
2020-02-04 19:02:11.254 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 30s
2020-02-04 19:02:13.058 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2020-02-04 19:02:13.060 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 6183)
2020-02-04 19:02:13.060 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1445 uncompressed 630 compressed bytes
2020-02-04 19:02:33.061 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 6184)
2020-02-04 19:02:33.061 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://172.24.102.69:8200/intake/v2/events
2020-02-04 19:02:33.063 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2020-02-04 19:02:41.255 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server http://172.24.102.69:8200/config/v1/agents
2020-02-04 19:02:42.944 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Configuration did not change
2020-02-04 19:02:42.944 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 30s
2020-02-04 19:02:43.064 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2020-02-04 19:02:43.070 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 6185)
2020-02-04 19:02:43.070 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1447 uncompressed 633 compressed bytes
2020-02-04 19:02:44.073 [apm-reporter] INFO co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Backing off for 0 seconds (+/-10%)
2020-02-04 19:02:44.074 [apm-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Error sending data to APM server: Server returned HTTP response code: 503 for URL: http://172.24.102.69:8200/intake/v2/events, response code is 503
2020-02-04 19:02:44.074 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Sending payload to APM server failed
java.io.IOException: Server returned HTTP response code: 503 for URL: http://172.24.102.69:8200/intake/v2/events
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1840)
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1441)
        at co.elastic.apm.agent.report.IntakeV2ReportingEventHandler.flush(IntakeV2ReportingEventHandler.java:224)
        at co.elastic.apm.agent.report.IntakeV2ReportingEventHandler.handleEvent(IntakeV2ReportingEventHandler.java:128)
        at co.elastic.apm.agent.report.IntakeV2ReportingEventHandler.onEvent(IntakeV2ReportingEventHandler.java:116)
        at co.elastic.apm.agent.report.IntakeV2ReportingEventHandler.onEvent(IntakeV2ReportingEventHandler.java:50)
        at co.elastic.apm.agent.shaded.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:168)
        at co.elastic.apm.agent.shaded.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125)
        at java.lang.Thread.run(Thread.java:745)
2020-02-04 19:02:44.074 [apm-reporter] WARN co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - {
  "accepted": 0,
  "errors": [
    {
      "message": "queue is full"
    }
  ]
}

2020-02-04 19:03:03.055 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 6186)
2020-02-04 19:03:03.056 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://172.24.102.69:8200/intake/v2/events
2020-02-04 19:03:03.057 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2020-02-04 19:03:12.944 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server http://172.24.102.69:8200/config/v1/agents
2020-02-04 19:03:12.992 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Configuration did not change
2020-02-04 19:03:12.992 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 30s
2020-02-04 19:03:13.057 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2020-02-04 19:03:13.066 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 6187)
2020-02-04 19:03:13.067 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1444 uncompressed 627 compressed bytes
2020-02-04 19:03:33.053 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 6188)
2020-02-04 19:03:33.053 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://172.24.102.69:8200/intake/v2/events
2020-02-04 19:03:33.055 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
4

From one that's working:

        at java.lang.Thread.run(Thread.java:745)
2020-02-04 19:02:18.752 [apm-reporter] WARN co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - {
  "accepted": 0,
  "errors": [
    {
      "message": "queue is full"
    }
  ]
}

2020-02-04 19:02:22.175 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server http://172.24.102.69:8200/config/v1/agents
2020-02-04 19:02:24.425 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Configuration did not change
2020-02-04 19:02:24.425 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 30s
2020-02-04 19:02:37.737 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 933)
2020-02-04 19:02:37.737 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://172.24.102.69:8200/intake/v2/events
2020-02-04 19:02:37.739 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2020-02-04 19:02:47.739 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2020-02-04 19:02:47.740 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 934)
2020-02-04 19:02:47.742 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1451 uncompressed 624 compressed bytes
2020-02-04 19:02:54.425 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server http://172.24.102.69:8200/config/v1/agents
2020-02-04 19:02:54.500 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Configuration did not change
2020-02-04 19:02:54.501 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 30s
2020-02-04 19:03:07.739 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 935)
2020-02-04 19:03:07.740 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://172.24.102.69:8200/intake/v2/events
2020-02-04 19:03:07.741 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2020-02-04 19:03:17.743 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2020-02-04 19:03:17.747 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 936)
2020-02-04 19:03:17.747 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1451 uncompressed 627 compressed bytes
2020-02-04 19:03:24.502 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server http://172.24.102.69:8200/config/v1/agents
2020-02-04 19:03:24.535 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Configuration did not change
2020-02-04 19:03:24.536 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 30s
2020-02-04 19:03:37.743 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 937)
2020-02-04 19:03:37.744 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://172.24.102.69:8200/intake/v2/events
2020-02-04 19:03:37.747 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2020-02-04 19:03:47.747 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2020-02-04 19:03:47.749 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 938)
2020-02-04 19:03:47.749 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1452 uncompressed 624 compressed bytes
2020-02-04 19:03:54.536 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server http://172.24.102.69:8200/config/v1/agents
2020-02-04 19:03:54.564 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Configuration did not change
2020-02-04 19:03:54.564 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 30s
2020-02-04 19:04:07.743 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 939)
2020-02-04 19:04:07.743 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://172.24.102.69:8200/intake/v2/events
2020-02-04 19:04:07.745 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2020-02-04 19:04:17.745 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2020-02-04 19:04:17.750 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 940)
2020-02-04 19:04:17.750 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1452 uncompressed 626 compressed bytes
2020-02-04 19:04:24.564 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server http://172.24.102.69:8200/config/v1/agents
2020-02-04 19:04:24.625 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Configuration did not change
2020-02-04 19:04:24.625 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 30s
2020-02-04 19:04:37.741 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 941)
2020-02-04 19:04:37.742 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://172.24.102.69:8200/intake/v2/events
2020-02-04 19:04:37.744 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2020-02-04 19:04:47.745 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2020-02-04 19:04:47.752 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 942)
2020-02-04 19:04:47.752 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1451 uncompressed 627 compressed bytes
2020-02-04 19:04:54.626 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server http://172.24.102.69:8200/config/v1/agents
2020-02-04 19:04:54.665 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Configuration did not change
2020-02-04 19:04:54.666 [apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 30s
2020-02-04 19:05:00.002 [pool-3-thread-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to '' 00-63670d2f8b6963a035806557ec3a449d-7e4323f1a8ff61a3-00 (6260049) (1)
2020-02-04 19:05:00.002 [pool-3-thread-1] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-63670d2f8b6963a035806557ec3a449d-7e4323f1a8ff61a3-00 (6260049) {
2020-02-04 19:05:00.002 [pool-3-thread-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'RequestUploadReportJob#execute' 00-63670d2f8b6963a035806557ec3a449d-7e4323f1a8ff61a3-00 (6260049) (2)
2020-02-04 19:05:00.002 [pool-3-thread-1] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating 'RequestUploadReportJob#execute' 00-63670d2f8b6963a035806557ec3a449d-7e4323f1a8ff61a3-00 (6260049) on thread 34
2020-02-04 19:05:00.036 [pool-3-thread-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'RequestUploadReportJob#execute' 00-63670d2f8b6963a035806557ec3a449d-7e4323f1a8ff61a3-00 (6260049) (3)
2020-02-04 19:05:00.043 [ActiveMQ Task-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'RequestUploadReportJob#execute' 00-63670d2f8b6963a035806557ec3a449d-7e4323f1a8ff61a3-00 (6260049) (4)
2020-02-04 19:05:00.043 [ActiveMQ Task-1] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating 'RequestUploadReportJob#execute' 00-63670d2f8b6963a035806557ec3a449d-7e4323f1a8ff61a3-00 (6260049) on thread 695
2020-02-04 19:05:00.073 [ActiveMQ Task-1] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'RequestUploadReportJob#execute' 00-63670d2f8b6963a035806557ec3a449d-7e4323f1a8ff61a3-00 (6260049) on thread 695
2020-02-04 19:05:00.073 [ActiveMQ Task-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'RequestUploadReportJob#execute' 00-63670d2f8b6963a035806557ec3a449d-7e4323f1a8ff61a3-00 (6260049) (3)
2020-02-04 19:05:00.073 [ActiveMQ Task-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'RequestUploadReportJob#execute' 00-63670d2f8b6963a035806557ec3a449d-7e4323f1a8ff61a3-00 (6260049) (2)
2020-02-04 19:05:00.073 [pool-3-thread-1] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'RequestUploadReportJob#execute' 00-63670d2f8b6963a035806557ec3a449d-7e4323f1a8ff61a3-00 (6260049) on thread 34
2020-02-04 19:05:00.073 [pool-3-thread-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'RequestUploadReportJob#execute' 00-63670d2f8b6963a035806557ec3a449d-7e4323f1a8ff61a3-00 (6260049) (1)
2020-02-04 19:05:00.073 [pool-3-thread-1] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'RequestUploadReportJob#execute' 00-63670d2f8b6963a035806557ec3a449d-7e4323f1a8ff61a3-00 (6260049)
2020-02-04 19:05:00.079 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 943)
2020-02-04 19:05:00.079 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://172.24.102.69:8200/intake/v2/events
2020-02-04 19:05:00.090 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2020-02-04 19:05:00.091 [apm-reporter] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'RequestUploadReportJob#execute' 00-63670d2f8b6963a035806557ec3a449d-7e4323f1a8ff61a3-00 (6260049) (0)
2020-02-04 19:05:07.740 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 944)
2020-02-04 19:05:10.090 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2020-02-04 19:05:10.090 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 945)
2020-02-04 19:05:10.091 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 2247 uncompressed 888 compressed bytes
5

Please upload the full logs, as described here: https://www.elastic.co/guide/en/apm/agent/java/current/trouble-shooting.html

6

Hi @felixbarny sorry about that.

Service with transactions:

Service without transactions:

7

For the application with transactions, the transactions are not due to HTTP traffic. They are created for @Scheduled-annotated methods like RequestUploadReportJob#execute.

Are you sure that these applications use Spring MVC to handle HTTP traffic? How do the controllers look like? Are they annotated with @RequestMapping?

Normally, if the agent detects that Spring's DispatcherServlet is being used, it instruments it and logs this on debug:

2020-02-05 15:11:02.991 [Thread-13] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation ServletInstrumentation: ((not(isInterface()) and hasSuperType(erasure(name(equals(javax.servlet.Servlet))))) and not(isInterface())) matches class org.springframework.web.servlet.DispatcherServlet
2020-02-05 15:11:02.992 [Thread-13] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation ExceptionHandlerInstrumentation: (name(equals(org.springframework.web.servlet.DispatcherServlet)) and not(isInterface())) matches class org.springframework.web.servlet.DispatcherServlet
2020-02-05 15:11:03.001 [Thread-13] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation ExceptionHandlerInstrumentation: (((((name(equals(processHandlerException)) and hasParameter(hasTypes(with(0 matches erasure(name(equals(javax.servlet.http.HttpServletRequest))))))) and hasParameter(hasTypes(with(1 matches erasure(name(equals(javax.servlet.http.HttpServletResponse))))))) and hasParameter(hasTypes(with(2 matches erasure(name(equals(java.lang.Object))))))) and hasParameter(hasTypes(with(3 matches erasure(name(equals(java.lang.Exception))))))) and returns(erasure(name(equals(org.springframework.web.servlet.ModelAndView))))) matches protected org.springframework.web.servlet.ModelAndView org.springframework.web.servlet.DispatcherServlet.processHandlerException(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse,java.lang.Object,java.lang.Exception) throws java.lang.Exception
8

Err... well, I don't have access to the source code, so it's possible you're right. I'll try to confirm, though. I do have another service that has HTTP activity and is properly instrumented. I'll add the logs soon.

For the non-working service, I can see similar logs to the one you mention about the servlet, followed by a warning that it can't be instrumented.

2020-02-05 14:08:21.286 [main] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation ExceptionHandlerInstrumentation: name(equals(org.springframework.web.servlet.DispatcherServlet)) matches class org.springframework.web.servlet.DispatcherServlet
2020-02-05 14:08:21.309 [main] WARN co.elastic.apm.agent.bci.bytebuddy.ErrorLoggingListener - org.springframework.web.servlet.DispatcherServlet uses an unsupported class file version (pre Java 5) and can't be instrumented. Consider updating to a newer version of that library.

I guess that's my problem? It's odd, though, how that the other HTTP ones work.

Also, I keep getting this for the instrumented transactions (scheduled and requests):

image
image1820×894 89.5 KB

Do you have any idea about that ("The selected trace cannot be found")?

9

Ah, that explains it. Seems like Spring 3 is compiled for Java 1.4. In theory it would be possible to instrument that but it would be a rabbit hole in terms of supporting such old versions. Any chance you can upgrade to Spring 4 or 5?

I've also seen these issues from time to time but I have no idea where they come from. Could you create a separate thread for this and make sure to add the ui tag?

10

I think the server errors have to do with the Elasticsearch machine having limited hardware capacity.

Thanks for the help.

11

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