New ES client doesn't log ES request body

[lukasolson]

Steps to reproduce:

1. Set elasticsearch.logQueries and logging.verbose to true inside your kibana.yml file
2. Load Discover

You'll see something along the following lines in your logs:

POST /aw-watcher-*/_async_search
wait_for_completion_timeout=100ms&keep_alive=1m&batched_reduce_size=64&ignore_unavailable=true&ignore_throttled=true&rest_total_hits_as_int=true&preference=1599005479136&track_total_hits=true

Prior to switching to the new JavaScript ES client, the entire request (including the body) would be logged. It doesn't appear the request body is being logged any more.

It's possible I'm missing something in my logging config that wasn't necessary before.

[elasticmachine]

Pinging @elastic/kibana-platform (Team:Platform)

[pgayvallet]

Not sure from where the body was logged in the legacy client. When looking at the code, I can't really see any difference between the two:

Legacy client:

kibana/src/core/server/elasticsearch/legacy/elasticsearch_client_config.ts

Lines 207 to 211 in 585d58c

	if (logQueries) {
	log.debug(`${statusCode}\n${method} ${options.path}\n${query ? query.trim() : ''}`, {
	tags: ['query'],
	});
	}

New client:

kibana/src/core/server/elasticsearch/client/configure_client.ts

Lines 46 to 60 in 9fa43b4

	if (event && logQueries) {
	const params = event.meta.request.params;
	// definition is wrong, `params.querystring` can be either a string or an object
	const querystring = convertQueryString(params.querystring);
	logger.debug(
	`${event.statusCode}\n${params.method} ${params.path}${
	querystring ? `\n${querystring}` : ''
	}`,
	{
	tags: ['query'],
	}
	);
	}

[mshustov]

@lukasolson Do you mean that in the legacy client we log query in stringified JSON format, but in the new client as a raw query string?

// new client
wait_for_completion_timeout=100ms&keep_alive=1m&batched_reduce_size=64&ignore_unavailable=true&ignore_throttled=true&rest_total_hits_as_int=true&preference=1599005479136&track_total_hits=true

// legacy client
{"seq_no_primary_term":true,"_source":{"excludes":["output.content"]},"query":{"bool":{"filter":{"bool":{"minimum_should_match":1,"should":[{"term":{"status":"pending"}},{"bool":{"must":[{"term":{"status":"processing"}},{"range":{"process_expiration":{"lte":"2020-09-02T09:54:47.355Z"}}}]}}]}}}},"sort":[{"priority":{"order":"asc"}},{"created_at":{"order":"asc"}}],"size":1}

We don't format them and rely on the elasticsearch client format in both cases.
Probably we need to keep the backward-compatible format.

[lukasolson]

Yeah, the new client is logging the query string, while the legacy client logged the Elasticsearch query (which is in the POST body).

[pgayvallet]

@delvedor Do you confirm this difference? From what @lukasolson says, it seems the query parameter of the legacy lib's logger trace method is the body payload?

kibana/src/core/server/elasticsearch/legacy/elasticsearch_client_config.ts

Lines 200 to 212 in 585d58c

	public trace(
	method: string,
	options: { path: string },
	query: string,
	_: unknown,
	statusCode: string
	) {
	if (logQueries) {
	log.debug(`${statusCode}\n${method} ${options.path}\n${query ? query.trim() : ''}`, {
	tags: ['query'],
	});
	}
	}

[delvedor]

The new client does not have an integrated logger, it has an event emitter interface which gives you full observability of what happening inside, see here.
Both the body and querystring will already be serialized once you get them.

[mshustov]

ok, we need to use event.meta.request.params.body instead of query. Also I noticed that the legacy client attaches query string to url

POST /.kibana_task_manager/_update_by_query?ignore_unavailable=true&refresh=true&max_docs=10&conflicts=proceed