Occasional HTTP 409 responses while adding fields in Discover

[NeonSludge]

Kibana version: 6.4.0

Elasticsearch version: 6.4.0

Server OS version: CentOS Linux release 7.4.1708 (Core) (Linux 4.14.12)

Browser version: Chrome 68.0.3440.106

Browser OS version: Windows 7 Enterprise x64

Original install method (e.g. download page, yum, from source, etc.): yum

Describe the bug:

Kibana sometimes receives an HTTP 409 Conflict response from Elasticsearch while adding fields to the main table from the "Available fields" panel in the Discover app. This results in an "Unable to write index pattern" error being displayed.

Logs from the load balancer that proxies requests to Elasticsearch show that POST requests to /<kibana index>/doc/index-pattern%3A<index pattern>/_update?version=<version>&refresh=wait_for normally take from 500 to 1000ms to complete.

This error did not occur in older versions of Kibana and Elasticsearch: there are no instances of HTTP 409 in the logs before the upgrade to 6.4.0.
Creating a new Kibana index and reindexing the old one to it did not produce any results.

Kibana index mappings: https://pastebin.com/raw/dXpMgzRW
Kibana index settings: https://pastebin.com/raw/AMypCU7Z
Kibana index stats: https://pastebin.com/raw/a7RqN4qH

Steps to reproduce:

1. Open Discover app, open any index (the document count doesn't seem to matter).
2. Start adding fields from the "Available fields" panel.
3. If you're not pausing for 2-3 seconds after every field then the following error is displayed via a standard Kibana popup: "Unable to write index pattern! Refresh the page to get the most up to date changes for this index pattern."
4. The field appears in the main table, there are no further issues with it.

Expected behavior:
No error is displayed when adding fields from the "Available fields" panel.

Errors in browser console (if relevant):
When the error is displayed in Kibana, this message is written to the browser console:
"Possibly unhandled rejection: {"res":{},"body":{"message":"[doc][index-pattern:waslogs-*]: version conflict, current version [15] is different than the one provided [14]: [version_conflict_engine_exception] [doc][index-pattern:waslogs-*]: version conflict, current version [15] is different than the one provided [14], with { index_uuid=\"3s7jLY9wSaOQK6TpQYoICw\" & shard=\"0\" & index=\".kibana-v6\" }","statusCode":409,"error":"Conflict"}}"
Here is the full browser console output dump.

Provide logs and/or server output (if relevant):
This is what Kibana writes to its own log:
Aug 27 20:31:33 <hostname> kibana[27854]: {"type":"response","@timestamp":"2018-08-27T17:31:32Z","tags":[],"pid":27854,"method":"put","statusCode":409,"req":{"url":"/api/saved_objects/index-pattern/waslogs-*","method":"put","headers":{"host":"kibana","connection":"close","content-length":"10143","origin":"http://<Nginx balancer>","kbn-version":"6.4.0","user-agent":"Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36","content-type":"application/json","accept":"*/*","referer":"http://<Nginx balancer>/app/kibana","accept-encoding":"gzip, deflate","accept-language":"en-US,en;q=0.9"},"remoteAddress":"<Nginx balancer>","userAgent":"<Nginx balancer>","referer":"http://<Nginx balancer>/app/kibana"},"res":{"statusCode":409,"responseTime":121,"contentLength":9},"message":"PUT /api/saved_objects/index-pattern/waslogs-* 409 121ms - 9.0B"}

Any additional context:
https://discuss.elastic.co/t/unable-to-write-index-pattern/146167/4

[NeonSludge]

I did some research.

So the culprit here is obviously the document update latency.
I've made a copy of the Kibana index with a single shard and no replicas and captured some sysdig data as well as a JFR from the JVM that runs the ES node that holds the shard.
It turns out, the index pattern update can take anywhere from 100ms to 5s. There is no evidence of any bottlenecks at the JVM or OS level: no excessive locking, no long GC pauses, no IO or network latency, no weird NUMA behaviour, etc.
All other indexing operations in the cluster and on this particular node perform well.

I've noticed that all the index pattern update requests generated by Kibana have the refresh parameter set to wait_for. According to the docs, this means that the request will wait for the next index refresh. So if the index refresh interval is large enough (5 seconds for the old index) and the update request lands just after a refresh, the index pattern update may take a long time. Even the default refresh interval of 1 second causes problems here if the index pattern is being updated frequently enough.

Here you can see the difference between two requests updating the same doc with refresh set to wait_for and true:

$ curl -s -w "%{time_total}" -o out -XPOST -H "content-type: application/json" "http://elasticsearch:9200/.kibana-6/doc/index-pattern%3Aa2e363a0-a9eb-11e8-8079-53a65e9a939b/_update?version=39&refresh=wait_for" -d@test.json
1.273

...
modify test.json so that the update is not a noop, increment version, set refresh to true
...

$ curl -s -w "%{time_total}" -o out -XPOST -H "content-type: application/json" "http://elasticsearch:9200/.kibana-6/doc/index-pattern%3Aa2e363a0-a9eb-11e8-8079-53a65e9a939b/_update?version=40&refresh=true" -d@test.json
0.025

Wouldn't it make sense to force a refresh every time the index pattern is updated, given that the Kibana index is usually very small?

[Bargs]

Nice detective work! Definitely seems like you identified the root issue. I'll need to give some thought to forcing a refresh on every update, I'll add this to my to do list.

[Bargs]

After playing with the refresh parameter and thinking about it some more, I think forcing the refresh could help but it won't be a cure all. Even with a forced refresh it's possible to interact with the UI quickly enough to generate a version conflict, especially if there's any network latency. To fix this for good, we really need to rewrite the way Kibana is doing these updates. When there's a version conflict we already attempt to merge the current change with the latest version, but I'm guessing this particular update fails because the fields in the index pattern are stored as one giant json string.

[Bargs]

Also, I realized the reason why this suddenly appeared in 6.4 is because of this change #18937

A good change overall, but this issue was a side effect.

[bhavyarm]

pinging @elastic/kibana-app @elastic/kibana-discovery

[jesusgn90]

[skbly7]

I am facing the same with ElasticSearch + Kibana version 6.7.2

[fdartayre]

@elastic/kibana-app any update on this issue? Seems that it still happens in 7.3.1.

[TinaHeiligers]

The issue is still present in master even when refresh is off:

[nickbabkin]

Still happens on Elastic Cloud latest version (7.4.0). Very annoying thing.

[jesusgn90]

Still happens on Elastic Cloud latest version (7.4.0). Very annoying thing.

The code didn't change, it's expected to see the same in 7.4, here you can see affected lines:

kibana/src/legacy/core_plugins/kibana/public/discover/controllers/discover.js

Lines 903 to 911 in 41fa2ef

	$scope.addColumn = function addColumn(columnName) {
	$scope.indexPattern.popularizeField(columnName, 1);
	columnActions.addColumn($scope.state.columns, columnName);
	};
	$scope.removeColumn = function removeColumn(columnName) {
	$scope.indexPattern.popularizeField(columnName, 1);
	columnActions.removeColumn($scope.state.columns, columnName);
	};

The line $scope.indexPattern.popularizeField(columnName, 1); changes the score for that field, however, if you are calling this method more than once and the first call didn't end yet, then you'll see the error because you are trying a second update and the first update is still in progress.

PS: I'm not from the Kibana team, so they can provide more in deep details about this, sorry.

[nickbabkin]

I have the 30s index refresh rate for some indices and this error just shows up pretty much every single time I add a new field in Kibana.