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