APM Java agent not tracking spans

Kibana version: 7.4.0

Elasticsearch version: 7.4.0

APM Server version: 7.4.1

APM Agent language and version: apm java agent: 1.16.0 AND 1.23.0 (tested both)

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):
Using apm to track transactions in my Java spring application. Here is my code:

@RestController
public class TestRest {
         @RequestMapping(value = "/", method = RequestMethod.GET)
	  public ResponseEntity<String> test () throws InterruptedException {
		  logMethod();
	      return new ResponseEntity<String>("OK", HttpStatus.OK);
	  }

       @CaptureSpan(value="delay")
	public void delay() {
		try {
			Thread.sleep(10000);
		} catch (InterruptedException e) {
			// TODO Auto-generated catch block
			e.printStackTrace();
		}
	}

       @CaptureSpan
	public void logMethod() throws InterruptedException {
			logger.info("INFO TEST");
			delay();
       }
}

I do not see the span for delay when calling the endpoint. I only see the rest.

Not sure how to solve this issue. I followed : Monitoring Java applications and Multiservice traces and correlated logs | Elastic Blog

Any help would be appreciated. Thanks

Hi, @Mohammad_Etemad
Can you set log_level to DEBUG and send logs?
what spring boot version do you use?

Spring version: 2.1.7

Here are some debug logs:

2021-04-22T18:00:33.081Z        INFO    [request]       middleware/log_middleware.go:76 request accepted        {"request_id": "f9d8e375-3e42-4d9b-a511-87e3db7bcd2f", "method": "POST", "URL": "/intake/v2/events", "content_length": -1, "remote_address": "", "user-agent": "elasticapm-java/1.23.0", "response_code": 202}
2021-04-22T18:00:33.082Z        DEBUG   [processors]    processing/processors.go:183    Publish event: {
  "@timestamp": "2021-04-22T18:00:13.061Z",
  "@metadata": {
    "beat": "apm-server",
    "type": "_doc",
    "version": "7.4.1",
    "pipeline": "apm"
  },
  "service": {
    "name": "test-app-6c67585558-jwz6t",
    "language": {
      "version": "1.8.0_151",
      "name": "Java"
    },
    "runtime": {
      "version": "1.8.0_151",
      "name": "Java"
    },
    "framework": {
      "name": "Spring Web MVC",
      "version": "5.1.9.RELEASE"
    }
  },
  "container": {
    "id": "3c67d9d08cebbbb38c65c88220629ecc5b5e504e8e7c9dd05fcf001e2c812d53"
  },
  "user_agent": {
    "original": "curl/7.29.0"
  },
  "transaction": {
    "id": "f8ff42d581f48897",
    "name": "TestRest#test",
    "duration": {
      "us": 10006380
    },
    "type": "request",
    "result": "HTTP 2xx",
    "sampled": true,
    "span_count": {
      "dropped": 0,
      "started": 0
    }
  },
  "kubernetes": {
    "pod": {
      "name": "test-app-6c67585558-jwz6t",
      "uid": "3dcb501f-bc67-4aee-ad98-9e2156240cfd"
    }
  },
  "client": {
    "ip": ""
  },
  "ecs": {
    "version": "1.1.0"
  },
  "processor": {
    "name": "transaction",
    "event": "transaction"
  },
  "agent": {
    "ephemeral_id": "80146ea9-d553-4846-bf03-0e1745144795",
    "name": "java",
    "version": "1.23.0"
  },
  "host": {
    "architecture": "amd64",
    "os": {
      "platform": "Linux"
    },
    "ip": ""
  },
  "http": {
    "version": "1.1",
    "request": {
      "headers": {
        "User-Agent": [
          "curl/7.29.0"
        ],
        "Host": [
          "localhost:8188"
        ],
        "Accept": [
          "*/*"
        ]
      },
      "socket": {
        "remote_address": "",
        "encrypted": false
      },
      "method": "get"
    },
    "response": {
      "headers_sent": true,
      "finished": true,
      "status_code": 200,
      "headers": {
        "Content-Type": [
          "text/plain;charset=UTF-8"
        ],
        "Content-Length": [
          "2"
        ],
        "Date": [
          "Thu, 22 Apr 2021 18:00:23 GMT"
        ]
      }
    }
  },
  "observer": {
    "version_major": 7,
    "id": "f8df7f24-22d5-4163-94f8-0060e5bb89f1",
    "ephemeral_id": "14c63327-ff11-4fa2-bc51-dab1d88bbabd",
    "type": "apm-server",
    "hostname": "host-1",
    "version": "7.4.1"
  },
  "process": {
    "title": "/usr/lib/jvm/java-1.8-openjdk/jre/bin/java",
    "pid": 8
  },
  "trace": {
    "id": "0ae80d1a0eaff7c21ba165a9b414f980"
  },
  "timestamp": {
    "us": 1619114413061015
  },
  "url": {
    "path": "/",
    "port": 8188,
    "scheme": "http",
    "full": "http://localhost:8188/",
    "domain": ""
  }
}
2021-04-22T18:00:34.142Z        DEBUG   [elasticsearch] elasticsearch/client.go:347     PublishEvents: 1 events have been published to elasticsearch in 59.828441ms.
2021-04-22T18:00:34.143Z        DEBUG   [publisher]     memqueue/ackloop.go:160 ackloop: receive ack [4: 0, 1]
2021-04-22T18:00:34.143Z        DEBUG   [publisher]     memqueue/eventloop.go:535       broker ACK events: count=1, start-seq=5, end-seq=5

Here are the debug logs from the agent inside my application when I do a REST request:

2021-04-22 18:20:08,724 [http-nio-8188-exec-3] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to '' 00-4ed58bcc4114e79f3fb185d88c5ce643-305a51bbf16daa21-01 (3afc7cb3) (1)
2021-04-22 18:20:08,726 [http-nio-8188-exec-3] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-4ed58bcc4114e79f3fb185d88c5ce643-305a51bbf16daa21-01 (3afc7cb3)
2021-04-22 18:20:08,726 [http-nio-8188-exec-3] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-4ed58bcc4114e79f3fb185d88c5ce643-305a51bbf16daa21-01 (3afc7cb3) on thread 39
2021-04-22 18:20:08,727 [http-nio-8188-exec-3] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to '' 00-4ed58bcc4114e79f3fb185d88c5ce643-305a51bbf16daa21-01 (3afc7cb3) (2)
DO I GET HERE?
2021-04-22T18:20:08,729 testApp test-app-7bc547d99f-b2cvl ${ctx:subscriber} ${ctx:device} INFO com.test.testApplication.TestRest http-nio-8188-exec-3 logMethod 29  INFO TEST
2021-04-22 18:20:09,499 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving JSON_WRITER event (sequence 4)
2021-04-22 18:20:09,499 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://localhost:8202/intake/v2/events
2021-04-22 18:20:09,502 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2021-04-22 18:20:18,733 [http-nio-8188-exec-3] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'TestRest#test' 00-4ed58bcc4114e79f3fb185d88c5ce643-305a51bbf16daa21-01 (3afc7cb3) on thread 39
2021-04-22 18:20:18,734 [http-nio-8188-exec-3] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'TestRest#test' 00-4ed58bcc4114e79f3fb185d88c5ce643-305a51bbf16daa21-01 (3afc7cb3) (1)
2021-04-22 18:20:18,734 [http-nio-8188-exec-3] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - endTransaction 'TestRest#test' 00-4ed58bcc4114e79f3fb185d88c5ce643-305a51bbf16daa21-01 (3afc7cb3)
2021-04-22 18:20:18,742 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 5)
2021-04-22 18:20:18,743 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'TestRest#test' 00-4ed58bcc4114e79f3fb185d88c5ce643-305a51bbf16daa21-01 (3afc7cb3) (0)
2021-04-22 18:20:19,502 [elastic-apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler$FlushOnTimeoutTimerTask - Request flush because the request timeout occurred
2021-04-22 18:20:19,511 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 6)
2021-04-22 18:20:19,512 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 3787 uncompressed 1464 compressed bytes

You need set application_packages Public API | APM Java Agent Reference [1.x] | Elastic

1 Like

Perfect, that worked. Thank you very much.

1 Like

For the record, we already have an open issue (#1502) to make instrumentation work by default without application_packages in order to avoid this kind of issues (at the price of making matching slower in your case).

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