No transaction data in APM

shalvah.deimos · February 4, 2020, 12:33pm

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.

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.

felixbarny · February 4, 2020, 12:59pm

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.

shalvah.deimos · February 4, 2020, 5:09pm

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

shalvah.deimos · February 4, 2020, 5:10pm

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

felixbarny · February 5, 2020, 8:08am

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

shalvah.deimos · February 5, 2020, 12:33pm

Hi @felixbarny sorry about that.

Service with transactions:

gist.github.com

https://gist.github.com/shalvah/8b4eed8ffc352862ce43dfc8943e1405

apm-working-service.log

2020-02-05 11:20:19.512 [apm-server-healthcheck] DEBUG co.elastic.apm.agent.report.ApmServerHealthChecker - Starting healthcheck to http://172.24.102.69:8200/
2020-02-05 11:20:19.522 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 10:net_cls:/
2020-02-05 11:20:19.522 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 9:memory:/
2020-02-05 11:20:19.523 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 8:hugetlb:/
2020-02-05 11:20:19.523 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 7:perf_event:/
2020-02-05 11:20:19.523 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 6:devices:/
2020-02-05 11:20:19.524 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 5:blkio:/
2020-02-05 11:20:19.524 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 4:freezer:/
2020-02-05 11:20:19.525 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 3:cpuset:/
2020-02-05 11:20:19.525 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 2:cpuacct,cpu:/

This file has been truncated. show original

Service without transactions:

gist.github.com

https://gist.github.com/shalvah/dc1a0d2b63c7958633f776ca3968c90a

apm-no-transactions-service.log

2020-02-05 14:08:14.431 [apm-server-healthcheck] DEBUG co.elastic.apm.agent.report.ApmServerHealthChecker - Starting healthcheck to http://172.24.102.69:8200/
2020-02-05 14:08:14.442 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 10:memory:/
2020-02-05 14:08:14.442 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 9:hugetlb:/
2020-02-05 14:08:14.442 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 8:devices:/
2020-02-05 14:08:14.443 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 7:blkio:/
2020-02-05 14:08:14.443 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 6:cpuacct,cpu:/
2020-02-05 14:08:14.443 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 5:net_cls:/
2020-02-05 14:08:14.450 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 4:freezer:/
2020-02-05 14:08:14.450 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 3:perf_event:/
2020-02-05 14:08:14.450 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 2:cpuset:/

This file has been truncated. show original

felixbarny · February 5, 2020, 2:52pm

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

shalvah.deimos · February 5, 2020, 3:55pm

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):

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

felixbarny · February 5, 2020, 4:48pm

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?

shalvah.deimos · February 10, 2020, 1:20pm

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

Thanks for the help.

system · March 2, 2020, 9:20am

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