Java Agent is sending empty? Transations/Span

Kibana version: 6.6.2

Elasticsearch version: 6.6.2

APM Server version: 6.6.2

APM Agent language and version: Java 1.8 with Java Agent 1.6.1

Browser version: Chrome 73

Original install method (e.g. download page, yum, deb, from source, etc.) and version:
rpm for server

Fresh install or upgraded from other version?
Upgrade of Elasticseatch and Kibana from 6.4.2
Fresh installation of APM-Server

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):
Empty span/transaction documents in Elasticsearch and error message on shown transactions in Kibana APM UI
image

Steps to reproduce:

  1. installed APM_Server with RPM and only changed Servername in Config
  2. Created a small java programm which connects to a Oracle database and executes a SELECT statement. The method in which the statement is called is annonated with @CaptureTransaction
  3. Execute the program.

Provide logs and/or server output (if relevant): no error messages in server log

It seems like there is no actual data sent to elasticsearch or apm with the transaction/span. (I see no data in the documents in both indices for span and transaction)

What information would help with the further analysis?

Edit:
Here the code that is executed (code within the function marked with @CaptureTransaction):

String sql = "SELECT * FROM DUAL";
System.out.println(sql);
try (PreparedStatement stmnt = conn.prepareStatement(sql)) {
	try (ResultSet result = stmnt.executeQuery()) {
		//ElasticApm.captureException(new Exception("Test"));
		while (result.next()) {
			System.out.println(result.getString(1));
		}
	}
}

In which view do you get the error? Could you attach the full JSON of the document which causes the errors?

Seems like there is some data sent to the APM Server:

2019-04-29 13:50:16.597 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 2)
2019-04-29 13:50:16.598 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1398 uncompressed 673 compressed bytes
2019-04-29 13:50:16.607 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 3)
2019-04-29 13:50:16.607 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://drs-s-els01:8200/intake/v2/events
2019-04-29 13:50:16.613 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2019-04-29 13:50:16.614 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 4)
2019-04-29 13:50:26.598 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SHUTDOWN event (sequence 5)
2019-04-29 13:50:26.600 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 952 uncompressed 524 compressed bytes

Could you set the log level to TRACE? That would print out the communication to the APM Server

Here the full agent log on log level TRACe

The error comes in the APM UI -> Traces -> and selecting an entry.
Side Fact: if i select the service in the APM UI I get a white screen with the following error in the browser console

TypeError: Cannot read property 'transaction' of undefined
    at render (/bundles/apm.bundle.js:2)
    at EuiBasicTable.renderItemFieldDataCell (/dlls/vendors.bundle.dll.js:89)
    at /dlls/vendors.bundle.dll.js:89
    at Array.forEach (<anonymous>)
    at EuiBasicTable.renderItemRow (/dlls/vendors.bundle.dll.js:89)
    at /dlls/vendors.bundle.dll.js:89
    at Array.map (<anonymous>)
    at EuiBasicTable.renderTableBody (/dlls/vendors.bundle.dll.js:89)
    at EuiBasicTable.renderTable (/dlls/vendors.bundle.dll.js:89)
    at EuiBasicTable.render (/dlls/vendors.bundle.dll.js:89)
    at l (/dlls/vendors.bundle.dll.js:212)
    at beginWork (/dlls/vendors.bundle.dll.js:212)
    at e (/dlls/vendors.bundle.dll.js:212)
    at f (/dlls/vendors.bundle.dll.js:212)
    at G (/dlls/vendors.bundle.dll.js:212)
    at x (/dlls/vendors.bundle.dll.js:212)

Here the documents that are in elasticsearch:
curl http://drs-s-els01:9200/apm-6.6.2-span*/_search?pretty

  "took" : 0,
  "timed_out" : false,
  "_shards" : {
    "total" : 1,
    "successful" : 1,
    "skipped" : 0,
    "failed" : 0
  },
  "hits" : {
    "total" : 4,
    "max_score" : 1.0,
    "hits" : [
      {
        "_index" : "apm-6.6.2-span-2019.04.29",
        "_type" : "doc",
        "_id" : "9ZbhaGoB5YyhnPC3MMCU",
        "_score" : 1.0
      },
      {
        "_index" : "apm-6.6.2-span-2019.04.29",
        "_type" : "doc",
        "_id" : "95bhaGoB5YyhnPC3MMCU",
        "_score" : 1.0
      },
      {
        "_index" : "apm-6.6.2-span-2019.04.29",
        "_type" : "doc",
        "_id" : "GaToaGoB5YyhnPC3tr5n",
        "_score" : 1.0
      },
      {
        "_index" : "apm-6.6.2-span-2019.04.29",
        "_type" : "doc",
        "_id" : "G6ToaGoB5YyhnPC3tr5n",
        "_score" : 1.0
      }
    ]
  }
}

curl http://drs-s-els01:9200/apm-6.6.2-tran*/_search?pretty

"hits" : [
      {
        "_index" : "apm-6.6.2-transaction-2019.04.29",
        "_type" : "doc",
        "_id" : "9pbhaGoB5YyhnPC3MMCU",
        "_score" : 1.0
      },
      {
        "_index" : "apm-6.6.2-transaction-2019.04.29",
        "_type" : "doc",
        "_id" : "-JbhaGoB5YyhnPC3MMCU",
        "_score" : 1.0
      },
      {
        "_index" : "apm-6.6.2-transaction-2019.04.29",
        "_type" : "doc",
        "_id" : "GqToaGoB5YyhnPC3tr5n",
        "_score" : 1.0
      },
      {
        "_index" : "apm-6.6.2-transaction-2019.04.29",
        "_type" : "doc",
        "_id" : "HKToaGoB5YyhnPC3tr5n",
        "_score" : 1.0
      },
      {
        "_index" : "apm-6.6.2-transaction-2019.04.29",
        "_type" : "doc",
        "_id" : "V6vuaGoB5YyhnPC3rZTk",
        "_score" : 1.0
      },
      {
        "_index" : "apm-6.6.2-transaction-2019.04.29",
        "_type" : "doc",
        "_id" : "HKvuaGoB5YyhnPC31N71",
        "_score" : 1.0
      },
      {
        "_index" : "apm-6.6.2-transaction-2019.04.29",
        "_type" : "doc",
        "_id" : "zeIiaWoB5YyhnPC3akeI",
        "_score" : 1.0
      },
      {
        "_index" : "apm-6.6.2-transaction-2019.04.29",
        "_type" : "doc",
        "_id" : "xOIiaWoB5YyhnPC3kXne",
        "_score" : 1.0
      }
    ]

The data sent to the APM Server actually looks good:

{"metadata":{"service":{"name":"apm-test","agent":{"name":"java","version":"1.6.1"},"language":{"name":"Java","version":"1.8.0_191"},"runtime":{"name":"Java","version":"1.8.0_191"},"version":null},"process":{"pid":16596,"title":"C:\\Program Files\\Java\\jre1.8.0_191\\bin\\java.exe"},"system":{"architecture":"amd64","hostname":"DRS-O-IT15","platform":"Windows 10"}}}
{"span":{"name":"SELECT","timestamp":1556542007183015,"id":"d5835e507c87a852","trace_id":"5896d8a89ee8dcf77636139812753a12","transaction_id":"ab85da341da4ae97","parent_id":"ab85da341da4ae97","duration":59.744,"stacktrace":[{"filename":"OraclePreparedStatementWrapper.java","function":"executeQuery","library_frame":true,"lineno":1491,"abs_path":"oracle.jdbc.driver.OraclePreparedStatementWrapper"},{"filename":"Main.java","function":"executeTestQuery","library_frame":false,"lineno":34,"abs_path":"com.***.apm.apm_test.Main"},{"filename":"Main.java","function":"main","library_frame":false,"lineno":22,"abs_path":"com.***.apm.apm_test.Main"}],"context":{"db":{"statement":"SELECT * FROM DUAL","type":"sql","user":"X_AWM"},"tags":{}},"type":"db.oracle.query"}}
{"transaction":{"timestamp":1556542007158005,"name":"Main#executeTestQuery","id":"ab85da341da4ae97","trace_id":"5896d8a89ee8dcf77636139812753a12","type":"request","duration":108.287,"context":{"tags":{}},"span_count":{"dropped":0,"started":1},"sampled":true}}

And it also seems like the APM Server did not send an error response back.

That looks really strange. There are transaction and span documents but they contain no data. I have never seen anything like that. Let me pull in some folks which may know more.

Are you using Logstash in between APM Server and Elasticsearch? Are there interesing events in the Elasticsearch log file?

I had the same issue. I forgot to close the span :wink:

No i send the events directly from the apm-server to elasticsearch.
Also there are no entries in the es-log for the input of the data only an error when i try to access the APM Dashboards (imported with the wizard in kibana)

[2019-04-30T06:35:30,224][DEBUG][o.e.a.s.TransportSearchAction] [DRS-S-ELS01] [apm-6.6.2-transaction-2019.04.30][0], node[hXdd9fXuROGvG9S4paS6mQ], [P], s[STARTED], a[id=LjRVRYKLSMKzfDd6WCBSlA]: Failed to execute [SearchRequest{searchType=QUERY_THEN_FETCH, indices=[apm-*], indicesOptions=IndicesOptions[ignore_unavailable=true, allow_no_indices=true, expand_wildcards_open=true, expand_wildcards_closed=false, allow_aliases_to_multiple_indices=true, forbid_closed_indices=true, ignore_aliases=false, ignore_throttled=true], types=[], routing='null', preference='1556598904288', requestCache=null, scroll=null, maxConcurrentShardRequests=5, batchedReduceSize=512, preFilterShardSize=64, allowPartialSearchResults=true, source={"size":0,"timeout":"30000ms","query":{"bool":{"must":[{"match_all":{"boost":1.0}},{"match_all":{"boost":1.0}},{"range":{"@timestamp":{"from":1556598014145,"to":1556598914145,"include_lower":true,"include_upper":true,"format":"epoch_millis","boost":1.0}}}],"adjust_pure_negative":true,"boost":1.0}},"_source":{"includes":[],"excludes":["sourcemap.sourcemap"]},"stored_fields":"*","docvalue_fields":[{"field":"@timestamp","format":"date_time"}],"script_fields":{"view errors":{"script":{"source":"doc['context.service.name'].value","lang":"painless"},"ignore_failure":false},"error id icon":{"script":{"source":"doc['error.grouping_key'].value","lang":"painless"},"ignore_failure":false}},"aggregations":{"2":{"terms":{"field":"transaction.name.keyword","size":1000,"min_doc_count":1,"shard_min_doc_count":0,"show_term_doc_count_error":false,"order":[{"1":"desc"},{"_key":"asc"}]},"aggregations":{"1":{"avg":{"field":"transaction.duration.us"}},"3":{"percentiles":{"field":"transaction.duration.us","percents":[95.0],"keyed":false,"tdigest":{"compression":100.0}}},"4":{"top_hits":{"from":0,"size":1,"version":false,"explain":false,"_source":{"includes":["transaction.id"],"excludes":[]},"docvalue_fields":[{"field":"transaction.id","format":"use_field_mapping"}],"sort":[{"@timestamp":{"order":"desc"}}]}},"5":{"top_hits":{"from":0,"size":1,"version":false,"explain":false,"_source":{"includes":["transaction.type"],"excludes":[]},"docvalue_fields":[{"field":"transaction.type","format":"use_field_mapping"}],"sort":[{"@timestamp":{"order":"desc"}}]}}}}}}}]
org.elasticsearch.transport.RemoteTransportException: [DRS-S-ELS01][10.49.80.180:9300][indices:data/read/search[phase/query]]
Caused by: java.lang.IllegalArgumentException: unable to fetch fields from _source field: _source is disabled in the mappings for index [apm-6.6.2-transaction-2019.04.30]
        at org.elasticsearch.search.fetch.subphase.FetchSourceSubPhase.hitExecute(FetchSourceSubPhase.java:52) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:167) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.search.aggregations.metrics.tophits.TopHitsAggregator.buildAggregation(TopHitsAggregator.java:168) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.search.aggregations.bucket.BucketsAggregator.bucketAggregations(BucketsAggregator.java:141) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.search.aggregations.bucket.terms.GlobalOrdinalsStringTermsAggregator.buildAggregation(GlobalOrdinalsStringTermsAggregator.java:238) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.search.aggregations.AggregationPhase.execute(AggregationPhase.java:130) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:120) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.indices.IndicesService.lambda$loadIntoContext$17(IndicesService.java:1237) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.indices.IndicesService.lambda$cacheShardLevelResult$18(IndicesService.java:1293) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.indices.IndicesRequestCache$Loader.load(IndicesRequestCache.java:164) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.indices.IndicesRequestCache$Loader.load(IndicesRequestCache.java:147) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.common.cache.Cache.computeIfAbsent(Cache.java:433) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.indices.IndicesRequestCache.getOrCompute(IndicesRequestCache.java:119) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.indices.IndicesService.cacheShardLevelResult(IndicesService.java:1299) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.indices.IndicesService.loadIntoContext(IndicesService.java:1235) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.search.SearchService.loadOrExecuteQueryPhase(SearchService.java:349) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:398) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.search.SearchService.access$100(SearchService.java:126) ~[elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.search.SearchService$2.onResponse(SearchService.java:360) [elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.search.SearchService$2.onResponse(SearchService.java:356) [elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.search.SearchService$4.doRun(SearchService.java:1117) [elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:759) [elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:41) [elasticsearch-6.6.2.jar:6.6.2]
        at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-6.6.2.jar:6.6.2]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_161]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_161]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]

@suikast42 I only use the automatic instrumentation of JDBC

1 Like

there seems to be something strange here because i see the duration of the Transaction in the APM UI but the transaction has no name? (Hadn't realised before that there is a duration in the view)

That explains a lot. With a disabled _source field, Kibana can't show the document in discover, as it relies on _source, just like the APM UI does.

Did you explicitly disable _source in the APM Server configuration? If you are unsure, could you paste your configuration here? Also include fields.yml, if present.

Yes you are correct the _source field was disabled in the apm-server config and that solved my whole problem!

Don't even know why i commented this line in...

Suggestion to prevent such a thing from happening again:
There was no hint in the file that the _source field is needed for the function of the whole APM-UI, so please add a hint in the config that this will kill the whole apm functionality (because the config option is ther only commented out and with a generic hint the the es docu) or remove the option from the template config.

1 Like

Thanks for the suggestion, I have created https://github.com/elastic/apm-server/issues/2152 accordingly

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