Kibana down because of Elasticsearch circuit_breaking_exception

Symptoms

We got a lot of alerts in infrastructure-alerts slack channel for:

Service probe on URL 'https://kibana.openfoodfacts.org/status' failed for more than 5 minutes.

Going to the status url we got a "server error".

Trying to diagnose and remedy

Base problem

On the machine, looking at kibana logs, while doing a request

docker-compose logs --tail=0 -f kibana

we see

kibana_1                  | {"type":"log","@timestamp":"2022-07-27T12:36:07+00:00","tags":["error","plugins","security","authentication"],"pid":1216,"message":"License is not available, authentication is not possible."}
kibana_1                  | {"type":"log","@timestamp":"2022-07-27T12:36:07+00:00","tags":["warning","plugins","licensing"],"pid":1216,"message":"License information could not be obtained from Elasticsearch due to {\"error\":{\"root_cause\":[{\"type\":\"circuit_breaking_exception\",\"reason\":\"[parent] Data too large, data for [<http_request>] would be [1028220976/980.5mb], which is larger than the limit of [1020054732/972.7mb], real usage: [1028220976/980.5mb], new bytes reserved: [0/0b], usages [request=0/0b, fielddata=0/0b, in_flight_requests=0/0b, model_inference=0/0b, eql_sequence=0/0b, accounting=76757928/73.2mb]\",\"bytes_wanted\":1028220976,\"bytes_limit\":1020054732,\"durability\":\"PERMANENT\"}],\"type\":\"circuit_breaking_exception\",\"reason\":\"[parent] Data too large, data for [<http_request>] would be [1028220976/980.5mb], which is larger than the limit of [1020054732/972.7mb], real usage: [1028220976/980.5mb], new bytes reserved: [0/0b], usages [request=0/0b, fielddata=0/0b, in_flight_requests=0/0b, model_inference=0/0b, eql_sequence=0/0b, accounting=76757928/73.2mb]\",\"bytes_wanted\":1028220976,\"bytes_limit\":1020054732,\"durability\":\"PERMANENT\"},\"status\":429} error"}

More memory

The day before, I gave more memory to ES to see if it was the problem, but it's not (see openfoodfacts-monitoring:#54).

Continue diagnosis

If we go on kibana container we can reproduce error:

docker-compose exec kibana bash

ES is there:

curl -XGET http://elasticsearch:9200

but we get the circuit_breaking_exception while querying

curl -XGET http://elasticsearch:9200/_license?pretty=true
{
  "error" : {
    "root_cause" : [
      {
        "type" : "circuit_breaking_exception",
        "reason" : "[parent] Data too large, data for [<http_request>] would be [1027528328/979.9mb], which is larger than the limit of [1020054732/972.7mb], real usage: [1027528328/979.9mb], new bytes reserved: [0/0b], usages [request=0/0b, fielddata=0/0b, in_flight_requests=0/0b, model_inference=0/0b, eql_sequence=0/0b, accounting=76607288/73mb]",
        "bytes_wanted" : 1027528328,
        "bytes_limit" : 1020054732,
        "durability" : "PERMANENT"
      }
    ],
    "type" : "circuit_breaking_exception",
    "reason" : "[parent] Data too large, data for [<http_request>] would be [1027528328/979.9mb], which is larger than the limit of [1020054732/972.7mb], real usage: [1027528328/979.9mb], new bytes reserved: [0/0b], usages [request=0/0b, fielddata=0/0b, in_flight_requests=0/0b, model_inference=0/0b, eql_sequence=0/0b, accounting=76607288/73mb]",
    "bytes_wanted" : 1027528328,
    "bytes_limit" : 1020054732,
    "durability" : "PERMANENT"
  },
  "status" : 429
}

trying to get stats for breaker:

curl -XGET elasticsearch:9200/_nodes/stats/breaker?pretty=true

we see:

"parent" : {
          "limit_size_in_bytes" : 1020054732,
          "limit_size" : "972.7mb",
          "estimated_size_in_bytes" : 1030370648,
          "estimated_size" : "982.6mb",
          "overhead" : 1.0,
          "tripped" : 39108
        }

Parent is the responsible for all memory according to amazon help center :

The parent circuit breaker (a circuit breaker type) is responsible for the overall memory usage of your cluster.

I tried to clear out fielddata cache:

curl -XPOST http://elasticsearch:9200/*/_cache/clear?fielddata=true

but it does not solve the problem.

Tunning parent circuit breaker

Comparing to reference documentation, our settings seems a bit low compared to defaults.

I will try to augment the parent size for now, and set it to real memory tracking.

Edited the docker-compose to add configuration (through environment variables):

  elasticsearch:
  ...
    environment:
    ...
      - "indices.breaker.total.use_real_memory=true"
      - "indices.breaker.request.limit=95%"

and restarted the container

docker-compose restart elasticsearch

It's not enough.

The issue might be that we have too much data (17Gb indexes)

Garbage collection ?

Is that maybe related to Garbage collection ? Listing /usr/share/elasticsearch/config/jvm.options in the container shows that G1GC is in use:

## GC configuration
8-13:-XX:+UseConcMarkSweepGC
8-13:-XX:CMSInitiatingOccupancyFraction=75
8-13:-XX:+UseCMSInitiatingOccupancyOnly

## G1GC Configuration
# NOTE: G1 GC is only supported on JDK version 10 or later
# to use G1GC, uncomment the next two lines and update the version on the
# following three lines to your version of the JDK
# 10-13:-XX:-UseConcMarkSweepGC
# 10-13:-XX:-UseCMSInitiatingOccupancyOnly
14-:-XX:+UseG1GC

line 14-: applies for we are on version 16 of the jdk:

# jdk/bin/java --version
openjdk 16.0.2 2021-07-20

Data size

In elasticsearch container:

curl localhost:9200/_cluster/stats?pretty=true

We got

 ...
 "segments" : {
      "count" : 2390,
      "memory_in_bytes" : 76423432,
      "terms_memory_in_bytes" : 65353984,
      "stored_fields_memory_in_bytes" : 1225392,
      "term_vectors_memory_in_bytes" : 0,
      "norms_memory_in_bytes" : 9117696,
      "points_memory_in_bytes" : 0,
      "doc_values_memory_in_bytes" : 726360,
      "index_writer_memory_in_bytes" : 35328144,
      "version_map_memory_in_bytes" : 0,
      "fixed_bit_set_memory_in_bytes" : 960,
      "max_unsafe_auto_id_timestamp" : 1658927252002,
      "file_sizes" : { }
    },
 ...
}

other memory values (for querycache or fielddata) ar 0 or near 0.

This is 188,175,008 bytes in total, which is 180m.

If we look at nodes using cat nodes API:

curl -XGET "localhost:9200/_cat/nodes?v=true&h=name,node*,heap*"
name         id   node.role   heap.current heap.percent heap.max
0665175f0369 3vOq cdfhilmrstw      978.5mb           95      1gb

we see two potential problems:

heap size is only 1gb (it should be 2 according to our heap settings)
our a node use 95% memory

Too many shards ?

following Es blog on memory troubleshooting

Over sharding is a usual suspect, let see:

# curl -XGET "localhost:9200/_cluster/health?filter_path=status,*_shards&pretty=true"
{
  "status" : "yellow",
  "active_primary_shards" : 317,
  "active_shards" : 317,
  "relocating_shards" : 0,
  "initializing_shards" : 0,
  "unassigned_shards" : 302,
  "delayed_unassigned_shards" : 0
}

while recommanded for our setting (2Gb) is 40 shards ! Also having unassigned_shards seems a bad news !

The problems comes from the fact that we have many indices. The ILM (Index Life Cycle Management) should prevent that, but it does not.

Repairing (backup then remove old indices)

More memory

First I need to snapshot to eventually clear some indices. But with the exception I can't do it, I can't even check a snapshot repository already exists:

$ curl -XGET 127.0.0.1:9200/_snapshot
{"error":{"root_cause":[{"type":"circuit_breaking_exception","reason":"[parent] Data too large, data for [<http_request>] would be [1026619992/979mb], which is larger than the limit of [1020054732/972.7mb], real usage: [1026619992/979mb], new bytes reserved: [0/0b], usages [request=0/0b, fielddata=815/815b, in_flight_request...

No choice then, we have to give ES enough memory to be able to handle current indices… we go for a hype of 8G. I change the docker-compose.yml:

  elasticsearch:
    ...
    environment:
      ...
      - "ES_JAVA_OPTS=-Xms8048m -Xmx8048m"
    ...
    mem_limit: 9g

But then again after a while we are blocked by the exception again :-( Even stranger, we have a larger than the limit of [1020054732/972.7mb]

circuit breaker limit was for request not total ! changed indices.breaker.request.limit=95% to indices.breaker.total.limit=95%. ... same result !

Snapshoting (backup)

Trying to backup:

modified docker-compose.yml to add

elasticsearch
    ...
    environment:
    ...
    - "path.repo=/opt/elasticsearch/backups"
    ...
    volumes:
    - elasticsearch-backup:/opt/elasticsearch

volumes:
...
elasticsearch-backup:

Create directories

docker-compose run --rm elasticsearch bash
cd /opt/elasticsearch
mkdir backups
chown elasticsearch /opt/elasticsearch/ -R

Recreated container

docker-compose rm -sf elasticsearch
docker-compose up -d elasticsearch

Created the snapshot repository

curl -X PUT "http://localhost:9200/_snapshot/backups?pretty" -H 'Content-Type: application/json'     -d'
{
  "type": "fs",
  "settings": {
    "location": "/opt/elasticsearch/backups"
  }
}
'

Note: (we had to retry several times because of circuit breaking exceptions)

get all indices names

curl -XGET "http://localhost:9200/*?pretty=true"|grep '^  "logs'

make a global snapshot, in a screen !!!

screen
...
curl -X PUT "localhost:9200/_snapshot/backups/2022-07-31?wait_for_completion=true&pretty" -H   'Content-Type: application/json' -d'
{
  "indices": [],
  "ignore_unavailable": true,
  "include_global_state": false,
  "metadata": {
    "taken_by": "alex",
    "taken_because": "backup before removing some indices"
  }
}
'

And it's a success !

{
"snapshot" : {
  "snapshot" : "2022-07-31",
  "uuid" : "kHQXBTGhQb-4-jH0m5mMfg",
  "repository" : "backups",
  "version_id" : 7140199,
  ...
  "state" : "SUCCESS",
  "start_time" : "2022-07-31T18:06:51.220Z",
  "start_time_in_millis" : 1659290811220,
  "end_time" : "2022-07-31T18:15:08.301Z",
  "end_time_in_millis" : 1659291308301,
  "duration_in_millis" : 497081,
  "failures" : [ ],
  "shards" : {
    "total" : 322,
    "failed" : 0,
    "successful" : 322
  },
  "feature_states" : [ ]
}
}

So we start removing indices !

Removing indices

Let's remove 2021 logs

curl -X DELETE "localhost:9200/logs-2021.*?pretty=true"

Is hard to pass, so we restart elasticsearch and try again… success.

Lets remove 2022.01… until 04

Finally it works !

Fixing Snapshot policy and ILM policy

It is a temporary fix… now we have to use kibana to setup a better policy (and maybe take ES memory down a bit again ?)

Create snapshot policy

In Kibana, go to Management -> Stack Management -> Snapshot and restore

In "Repositories" we see the backups repository that was created before, pointing to /opt/elasticsearch/backups

Remember that we had to edit the docker-compose.yml file to add the path.repo environment variable and the elasticsearch-backup volume.

In "Policies", we create a policy named weekly-snapshots as follow:

Snapshot name: <weekly-snap-{now/d}>
Repository: backups
Schedule : weekly
Data streams and indices: All indices
Ignore unavailable indices: No
Allow partial shards: No
Include global state: Yes
Retention: delete after 360d
Min count: 20

Create Index Lifecycle Management policy

This part is very important. Logs are creating a lot of indices (as logrotate would) and so we have to automatically manage what happens with old indices so that we do not go beyond hardware capabilities (too much indices takes too much memory). ES has a mechanism for that called Index Lifecycle Management (ILM).

In Kibana, go to Management -> Stack Management -> Index Lifecycle Policy

There is already a log policy. Edit it to have this:

Hot phase (the phase where the index is the active index for logs)
- Roll over : use recommended defaults
- set index priority to 100
Warm phase (the phase where the index is history of logs, you want to search)
- Move data into phase when 58 days old
- replicas: 0
- Shrink: to 1
- Force merge to 1 + compress
- mark read only
- index priority: 50
Cold phase (historical data, last phase before removal)
- Move data into phase when: 119 days old
- Do not make them searchable
Delete phase:
- move data intor phase when 240 days old
- Wait for snapshot policy: weekly-snapshots

Attach policy to index template

Attach the logs policy you edited to the logs index template.

In Management -> Stack Management -> Index Lifecycle Policy,

On the line corresponding to logs policy, use Action button + Add policy to index template
Set template to logs
Set alias to logs-current

We notice that logs template pattern was not coherent, as it was logs-*-*, so we also add logs-*.*.* that match our indexes names. To do this goes to Management -> Stack Management -> Index Management -> Index Templates, and edit the logs template.

Now we have to create the active alias. It should correspond to our last index. This was logs-2022.08.18 at time of writing.

In the Dev Tool -> Console, we run:

POST _aliases
{
  "actions": [
    {
      "add": {
        "index": "logs-2022.08.18",
        "alias": "logs-current",
         "is_write_index": true
      }
    }
  ]
}

We then go to Management -> Stack Management -> Index Management

Select logs-2022.08.18 and use "Manage" apply log policy, with:

policy: logs
alias: logs-current

Attach old index to a policy

This will add it for future indices, but we want to add it to existing indices (we follow ES doc, section Manage existing indices).

going to Management -> Stack Management -> Index Lifecycle Policy we create a policy that is exactly the same as logs policy but:
- name is logs-old
- rollover is disabled
we apply it to 05 logs, in Dev Tool -> Console, by running (put the unix timestamp value corresponding to the month in origination_date¹):
```
PUT logs-2022.05.*/_settings
{
  "index": {
    "lifecycle": {
      "name": "logs-old"
      "origination_date": "xxxxx"
    }
  }
}
```
we do the same for every monthes until 08, but beware not to apply it to 2022.08.18 !

Useful resources

About circuit breaker exception:

https://aws.amazon.com/premiumsupport/knowledge-center/opensearch-circuit-breaker-exception/
https://www.elastic.co/blog/improving-node-resiliency-with-the-real-memory-circuit-breaker
https://www.elastic.co/guide/en/elasticsearch/reference/7.0/circuit-breaker.html#parent-circuit-breaker

About index lifecycle management (ILM):

https://www.elastic.co/guide/en/elasticsearch/reference/current/getting-started-index-lifecycle-management.html
https://www.elastic.co/guide/en/elasticsearch/reference/current/index-lifecycle-management.html

Footnotes

this is the timestamp used to calculate the index age for its phase transitions. If not specified, today date is taken. see documentation. You can get timestamp, eg in python with datetime(year, month, date).timestamp(). ↩

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

2022-07-kibana-down-es-circuit-breaking-exception.md

2022-07-kibana-down-es-circuit-breaking-exception.md

Kibana down because of Elasticsearch circuit_breaking_exception

Symptoms

Trying to diagnose and remedy

Base problem

More memory

Continue diagnosis

Tunning parent circuit breaker

Garbage collection ?

Data size

Too many shards ?

Repairing (backup then remove old indices)

More memory

Snapshoting (backup)

Removing indices

Fixing Snapshot policy and ILM policy

Create snapshot policy

Create Index Lifecycle Management policy

Attach policy to index template

Attach old index to a policy

Useful resources

Files

2022-07-kibana-down-es-circuit-breaking-exception.md

Latest commit

History

2022-07-kibana-down-es-circuit-breaking-exception.md

File metadata and controls

Kibana down because of Elasticsearch circuit_breaking_exception

Symptoms

Trying to diagnose and remedy

Base problem

More memory

Continue diagnosis

Tunning parent circuit breaker

Garbage collection ?

Data size

Too many shards ?

Repairing (backup then remove old indices)

More memory

Snapshoting (backup)

Removing indices

Fixing Snapshot policy and ILM policy

Create snapshot policy

Create Index Lifecycle Management policy

Attach policy to index template

Attach old index to a policy

Useful resources

Footnotes