Negative used memory in QueryCacheStats causes IllegalArgumentException in _cat/nodes

[cristi-]

Describe the feature:

Elasticsearch version (bin/elasticsearch --version): 7.6.0

Plugins installed: [analysis-icu analysis-kuramoji es-restlog es-shopname-tokenizer repository-gcs]

JVM version (java -version):
openjdk version "13.0.2" 2020-01-14
OS version (uname -a if on a Unix-like system):
Linux elastic2-es-data-14 4.14.138+ #1 SMP Tue Sep 3 02:58:08 PDT 2019 x86_64 x86_64 x86_64 GNU/Linux

Description of the problem including expected versus actual behavior:

Running curl localhost:9200/_nodes/_local/stats?error_trace=true on a data node shows the following stack trace:

{
  "error": {
    "root_cause": [
      {
        "type": "illegal_argument_exception",
        "reason": "Values less than -1 bytes are not supported: -6b",
        "stack_trace": "[Values less than -1 bytes are not supported: -6b]; nested: IllegalArgumentException[Values less than -1 bytes are not supported: -6b];\n\tat org.elasticsearch.ElasticsearchException.guessRootCauses(ElasticsearchException.java:644)\n\tat org.elasticsearch.ElasticsearchException.generateFailureXContent(ElasticsearchException.java:572)\n\tat org.elasticsearch.rest.BytesRestResponse.build(BytesRestResponse.java:138)\n\tat org.elasticsearch.rest.BytesRestResponse.<init>(BytesRestResponse.java:96)\n\tat org.elasticsearch.rest.BytesRestResponse.<init>(BytesRestResponse.java:91)\n\tat org.elasticsearch.rest.action.RestActionListener.onFailure(RestActionListener.java:58)\n\tat org.elasticsearch.rest.action.RestActionListener.onResponse(RestActionListener.java:49)\n\tat org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:70)\n\tat org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:64)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.finishHim(TransportNodesAction.java:236)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.onOperation(TransportNodesAction.java:213)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.access$000(TransportNodesAction.java:142)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:191)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:183)\n\tat org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleResponse(TransportService.java:1108)\n\tat org.elasticsearch.transport.TransportService$DirectResponseChannel.processResponse(TransportService.java:1186)\n\tat org.elasticsearch.transport.TransportService$DirectResponseChannel.sendResponse(TransportService.java:1166)\n\tat org.elasticsearch.transport.TaskTransportChannel.sendResponse(TaskTransportChannel.java:54)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$NodeTransportHandler.messageReceived(TransportNodesAction.java:244)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$NodeTransportHandler.messageReceived(TransportNodesAction.java:240)\n\tat org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:63)\n\tat org.elasticsearch.transport.TransportService$7.doRun(TransportService.java:750)\n\tat org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:692)\n\tat org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\n\tat java.base/java.lang.Thread.run(Thread.java:830)\nCaused by: java.lang.IllegalArgumentException: Values less than -1 bytes are not supported: -6b\n\tat org.elasticsearch.common.unit.ByteSizeValue.<init>(ByteSizeValue.java:72)\n\tat org.elasticsearch.common.unit.ByteSizeValue.<init>(ByteSizeValue.java:67)\n\tat org.elasticsearch.index.cache.query.QueryCacheStats.getMemorySize(QueryCacheStats.java:73)\n\tat org.elasticsearch.index.cache.query.QueryCacheStats.toXContent(QueryCacheStats.java:130)\n\tat org.elasticsearch.action.admin.indices.stats.CommonStats.toXContent(CommonStats.java:510)\n\tat org.elasticsearch.indices.NodeIndicesStats.toXContent(NodeIndicesStats.java:202)\n\tat org.elasticsearch.action.admin.cluster.node.stats.NodeStats.toXContent(NodeStats.java:284)\n\tat org.elasticsearch.action.admin.cluster.node.stats.NodesStatsResponse.toXContent(NodesStatsResponse.java:61)\n\tat org.elasticsearch.rest.action.RestActions.nodesResponse(RestActions.java:183)\n\tat org.elasticsearch.rest.action.RestActions$NodesResponseRestListener.buildResponse(RestActions.java:232)\n\tat org.elasticsearch.rest.action.RestActions$NodesResponseRestListener.buildResponse(RestActions.java:223)\n\tat org.elasticsearch.rest.action.RestBuilderListener.buildResponse(RestBuilderListener.java:38)\n\tat org.elasticsearch.rest.action.RestResponseListener.processResponse(RestResponseListener.java:37)\n\tat org.elasticsearch.rest.action.RestActionListener.onResponse(RestActionListener.java:47)\n\t... 20 more\n\tSuppressed: java.lang.IllegalStateException: Failed to close the XContentBuilder\n\t\tat org.elasticsearch.common.xcontent.XContentBuilder.close(XContentBuilder.java:1011)\n\t\tat org.elasticsearch.rest.action.RestBuilderListener.buildResponse(RestBuilderListener.java:37)\n\t\t... 22 more\n\tCaused by: java.io.IOException: Unclosed object or array found\n\t\tat org.elasticsearch.common.xcontent.json.JsonXContentGenerator.close(JsonXContentGenerator.java:469)\n\t\tat org.elasticsearch.common.xcontent.XContentBuilder.close(XContentBuilder.java:1009)\n\t\t... 23 more\n"
      }
    ],
    "type": "illegal_argument_exception",
    "reason": "Values less than -1 bytes are not supported: -6b",
    "stack_trace": "java.lang.IllegalArgumentException: Values less than -1 bytes are not supported: -6b\n\tat org.elasticsearch.common.unit.ByteSizeValue.<init>(ByteSizeValue.java:72)\n\tat org.elasticsearch.common.unit.ByteSizeValue.<init>(ByteSizeValue.java:67)\n\tat org.elasticsearch.index.cache.query.QueryCacheStats.getMemorySize(QueryCacheStats.java:73)\n\tat org.elasticsearch.index.cache.query.QueryCacheStats.toXContent(QueryCacheStats.java:130)\n\tat org.elasticsearch.action.admin.indices.stats.CommonStats.toXContent(CommonStats.java:510)\n\tat org.elasticsearch.indices.NodeIndicesStats.toXContent(NodeIndicesStats.java:202)\n\tat org.elasticsearch.action.admin.cluster.node.stats.NodeStats.toXContent(NodeStats.java:284)\n\tat org.elasticsearch.action.admin.cluster.node.stats.NodesStatsResponse.toXContent(NodesStatsResponse.java:61)\n\tat org.elasticsearch.rest.action.RestActions.nodesResponse(RestActions.java:183)\n\tat org.elasticsearch.rest.action.RestActions$NodesResponseRestListener.buildResponse(RestActions.java:232)\n\tat org.elasticsearch.rest.action.RestActions$NodesResponseRestListener.buildResponse(RestActions.java:223)\n\tat org.elasticsearch.rest.action.RestBuilderListener.buildResponse(RestBuilderListener.java:38)\n\tat org.elasticsearch.rest.action.RestResponseListener.processResponse(RestResponseListener.java:37)\n\tat org.elasticsearch.rest.action.RestActionListener.onResponse(RestActionListener.java:47)\n\tat org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:70)\n\tat org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:64)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.finishHim(TransportNodesAction.java:236)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.onOperation(TransportNodesAction.java:213)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.access$000(TransportNodesAction.java:142)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:191)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:183)\n\tat org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleResponse(TransportService.java:1108)\n\tat org.elasticsearch.transport.TransportService$DirectResponseChannel.processResponse(TransportService.java:1186)\n\tat org.elasticsearch.transport.TransportService$DirectResponseChannel.sendResponse(TransportService.java:1166)\n\tat org.elasticsearch.transport.TaskTransportChannel.sendResponse(TaskTransportChannel.java:54)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$NodeTransportHandler.messageReceived(TransportNodesAction.java:244)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$NodeTransportHandler.messageReceived(TransportNodesAction.java:240)\n\tat org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:63)\n\tat org.elasticsearch.transport.TransportService$7.doRun(TransportService.java:750)\n\tat org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:692)\n\tat org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\n\tat java.base/java.lang.Thread.run(Thread.java:830)\n\tSuppressed: java.lang.IllegalStateException: Failed to close the XContentBuilder\n\t\tat org.elasticsearch.common.xcontent.XContentBuilder.close(XContentBuilder.java:1011)\n\t\tat org.elasticsearch.rest.action.RestBuilderListener.buildResponse(RestBuilderListener.java:37)\n\t\t... 22 more\n\tCaused by: java.io.IOException: Unclosed object or array found\n\t\tat org.elasticsearch.common.xcontent.json.JsonXContentGenerator.close(JsonXContentGenerator.java:469)\n\t\tat org.elasticsearch.common.xcontent.XContentBuilder.close(XContentBuilder.java:1009)\n\t\t... 23 more\n",
    "suppressed": [
      {
        "type": "illegal_state_exception",
        "reason": "Failed to close the XContentBuilder",
        "caused_by": {
          "type": "i_o_exception",
          "reason": "Unclosed object or array found",
          "stack_trace": "java.io.IOException: Unclosed object or array found\n\tat org.elasticsearch.common.xcontent.json.JsonXContentGenerator.close(JsonXContentGenerator.java:469)\n\tat org.elasticsearch.common.xcontent.XContentBuilder.close(XContentBuilder.java:1009)\n\tat org.elasticsearch.rest.action.RestBuilderListener.buildResponse(RestBuilderListener.java:37)\n\tat org.elasticsearch.rest.action.RestResponseListener.processResponse(RestResponseListener.java:37)\n\tat org.elasticsearch.rest.action.RestActionListener.onResponse(RestActionListener.java:47)\n\tat org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:70)\n\tat org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:64)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.finishHim(TransportNodesAction.java:236)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.onOperation(TransportNodesAction.java:213)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.access$000(TransportNodesAction.java:142)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:191)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:183)\n\tat org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleResponse(TransportService.java:1108)\n\tat org.elasticsearch.transport.TransportService$DirectResponseChannel.processResponse(TransportService.java:1186)\n\tat org.elasticsearch.transport.TransportService$DirectResponseChannel.sendResponse(TransportService.java:1166)\n\tat org.elasticsearch.transport.TaskTransportChannel.sendResponse(TaskTransportChannel.java:54)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$NodeTransportHandler.messageReceived(TransportNodesAction.java:244)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$NodeTransportHandler.messageReceived(TransportNodesAction.java:240)\n\tat org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:63)\n\tat org.elasticsearch.transport.TransportService$7.doRun(TransportService.java:750)\n\tat org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:692)\n\tat org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\n\tat java.base/java.lang.Thread.run(Thread.java:830)\n"
        },
        "stack_trace": "java.lang.IllegalStateException: Failed to close the XContentBuilder\n\tat org.elasticsearch.common.xcontent.XContentBuilder.close(XContentBuilder.java:1011)\n\tat org.elasticsearch.rest.action.RestBuilderListener.buildResponse(RestBuilderListener.java:37)\n\tat org.elasticsearch.rest.action.RestResponseListener.processResponse(RestResponseListener.java:37)\n\tat org.elasticsearch.rest.action.RestActionListener.onResponse(RestActionListener.java:47)\n\tat org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:70)\n\tat org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:64)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.finishHim(TransportNodesAction.java:236)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.onOperation(TransportNodesAction.java:213)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.access$000(TransportNodesAction.java:142)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:191)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:183)\n\tat org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleResponse(TransportService.java:1108)\n\tat org.elasticsearch.transport.TransportService$DirectResponseChannel.processResponse(TransportService.java:1186)\n\tat org.elasticsearch.transport.TransportService$DirectResponseChannel.sendResponse(TransportService.java:1166)\n\tat org.elasticsearch.transport.TaskTransportChannel.sendResponse(TaskTransportChannel.java:54)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$NodeTransportHandler.messageReceived(TransportNodesAction.java:244)\n\tat org.elasticsearch.action.support.nodes.TransportNodesAction$NodeTransportHandler.messageReceived(TransportNodesAction.java:240)\n\tat org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:63)\n\tat org.elasticsearch.transport.TransportService$7.doRun(TransportService.java:750)\n\tat org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:692)\n\tat org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\n\tat java.base/java.lang.Thread.run(Thread.java:830)\nCaused by: java.io.IOException: Unclosed object or array found\n\tat org.elasticsearch.common.xcontent.json.JsonXContentGenerator.close(JsonXContentGenerator.java:469)\n\tat org.elasticsearch.common.xcontent.XContentBuilder.close(XContentBuilder.java:1009)\n\t... 23 more\n"
      }
    ]
  },
  "status": 400
}

The following settings were changed(probably not relevant):

cluster.routing.use_adaptive_replica_selection: false
indices.breaker.total.use_real_memory: false

Steps to reproduce:

This is a k8s elasticsearch cluster. Unfortunately I am not sure how to reproduce. Restarting the bad data node fixes the issue.

Provide logs (if relevant):

[droberts195]

This sounds like the same problem as #54415.

[elasticmachine]

Pinging @elastic/es-core-features (:Core/Features/CAT APIs)

[geekpete]

Do we know what scenarios this might be triggered under (any docker environment, some docker environments, all ESS/ECE environments?) and if particular JVM versions are part of the trigger (eg if bundled JVM version will always hit this issue once combined with specific docker environments or if specific combinations of self-hosted versions and use of particular non-bundled JVM versions will hit this)? Or put another way, what do we tell customers to watch out for.

[jakelandis]

@danhermann - Am i correct in reading this that #56412 won't fix this flavor of the issue ?

[danhermann]

@danhermann - Am i correct in reading this that #56412 won't fix this flavor of the issue ?

@jakelandis, you are correct that #56412 will not fix this issue with the reported query cache size. It addresses only the negative values reported by the OS for memory and swap. The same "fix" could be applied here by returning zero any time the query cache size is seen as negative, but I'd hesitate to do that here. For the case of OS memory and swap, we confirmed that there were cases where either the platform or JVM could erroneously report negative values so we were not just covering up a bug in our tracking of memory and swap sizes (or, at least, not necessarily doing that). In the case of query cache size, as I read the code, that's tracked entirely in ES and so any negative values there must be the result of a bug in the query cache size tracking code.

[RicardoGralhoz]

I also saw this issue on a 13-node cluster with Elasticsearch v7.10.1, Ubuntu 18.04.2 LTS, OpenJDK 64-Bit v11.0.3, using G1GC, with 32GiB of memory, setting 16GB for JVM heap, IHOP 30% and reserving 25% for G1. I've seen it on 7.1.0 and 7.8.1, same VMs.

Please see more details on the cluster specs and discussions on this forum topic:
help-with-unassigned-shards-circuitbreakingexception-values-less-than-1-bytes-are-not-supported

Here is one stack trace of the http:://localhost:9200/_nodes/stats/fs,jvm,indices,breaker?error_trace=true API response

Dec 25 2020 14:36:29.947 (PST)

{
  "error": {
    "root_cause": [{
      "type": "illegal_argument_exception",
      "reason": "Values less than -1 bytes are not supported: -4b",
      "stack_trace": [Values less than -1 bytes are not supported: -4b]; nested: IllegalArgumentException[Values less than -1 bytes are not supported: -4b];
          at org.elasticsearch.ElasticsearchException.guessRootCauses(ElasticsearchException.java:644)
          at org.elasticsearch.ElasticsearchException.generateFailureXContent(ElasticsearchException.java:572)
          at org.elasticsearch.rest.BytesRestResponse.build(BytesRestResponse.java:149)
          at org.elasticsearch.rest.BytesRestResponse.<init>(BytesRestResponse.java:110)
          at org.elasticsearch.rest.BytesRestResponse.<init>(BytesRestResponse.java:93)
          at org.elasticsearch.rest.action.RestActionListener.onFailure(RestActionListener.java:58)
          at org.elasticsearch.rest.action.RestActionListener.onResponse(RestActionListener.java:49)
          at org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:89)
          at org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:83)
          at org.elasticsearch.action.ActionRunnable.lambda$supply$0(ActionRunnable.java:58)
          at org.elasticsearch.action.ActionRunnable$2.doRun(ActionRunnable.java:73)
          at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
          at org.elasticsearch.common.util.concurrent.EsExecutors$DirectExecutorService.execute(EsExecutors.java:224)
          at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.finishHim(TransportNodesAction.java:263)
          at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.onOperation(TransportNodesAction.java:248)
          at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.access$000(TransportNodesAction.java:177)
          at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:226)
          at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:218)
          at org.elasticsearch.transport.TransportService$6.handleResponse(TransportService.java:634)
          at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleResponse(TransportService.java:1171)
          at org.elasticsearch.transport.InboundHandler.doHandleResponse(InboundHandler.java:253)
          at org.elasticsearch.transport.InboundHandler.handleResponse(InboundHandler.java:245)
          at org.elasticsearch.transport.InboundHandler.messageReceived(InboundHandler.java:133)
          at org.elasticsearch.transport.InboundHandler.inboundMessage(InboundHandler.java:89)
          at org.elasticsearch.transport.TcpTransport.inboundMessage(TcpTransport.java:700)
          at org.elasticsearch.transport.InboundPipeline.forwardFragments(InboundPipeline.java:142)
          at org.elasticsearch.transport.InboundPipeline.doHandleBytes(InboundPipeline.java:117)
          at org.elasticsearch.transport.InboundPipeline.handleBytes(InboundPipeline.java:82)
          at org.elasticsearch.transport.netty4.Netty4MessageChannelHandler.channelRead(Netty4MessageChannelHandler.java:74)
          at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
          at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
          at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
          at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:271)
          at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
          at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
          at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
          at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
          at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
          at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
          at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
          at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
          at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
          at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:615)
          at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:578)
          at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
          at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
          at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
          at java.base/java.lang.Thread.run(Thread.java:832)
          used by: java.lang.IllegalArgumentException: Values less than -1 bytes are not supported: -4b
          at org.elasticsearch.common.unit.ByteSizeValue.<init>(ByteSizeValue.java:79)
          at org.elasticsearch.common.unit.ByteSizeValue.<init>(ByteSizeValue.java:74)
          at org.elasticsearch.index.cache.query.QueryCacheStats.getMemorySize(QueryCacheStats.java:73)
          at org.elasticsearch.index.cache.query.QueryCacheStats.toXContent(QueryCacheStats.java:130)
          at org.elasticsearch.action.admin.indices.stats.CommonStats.toXContent(CommonStats.java:510)
          at org.elasticsearch.indices.NodeIndicesStats.toXContent(NodeIndicesStats.java:202)
          at org.elasticsearch.action.admin.cluster.node.stats.NodeStats.toXContent(NodeStats.java:324)
          at org.elasticsearch.action.admin.cluster.node.stats.NodesStatsResponse.toXContent(NodesStatsResponse.java:61)
          at org.elasticsearch.rest.action.RestActions.nodesResponse(RestActions.java:184)
          at org.elasticsearch.rest.action.RestActions$NodesResponseRestListener.buildResponse(RestActions.java:237)
          at org.elasticsearch.rest.action.RestActions$NodesResponseRestListener.buildResponse(RestActions.java:228)
          at org.elasticsearch.rest.action.RestBuilderListener.buildResponse(RestBuilderListener.java:38)
          at org.elasticsearch.rest.action.RestResponseListener.processResponse(RestResponseListener.java:37)
          at org.elasticsearch.rest.action.RestActionListener.onResponse(RestActionListener.java:47)
          ... 41 more
          Suppressed: java.lang.IllegalStateException: Failed to close the XContentBuilder
          at org.elasticsearch.common.xcontent.XContentBuilder.close(XContentBuilder.java:1017)
          at org.elasticsearch.rest.action.RestBuilderListener.buildResponse(RestBuilderListener.java:37)
          ... 43 more
          Caused by: java.io.IOException: Unclosed object or array found
          at org.elasticsearch.common.xcontent.json.JsonXContentGenerator.close(JsonXContentGenerator.java:456)
          at org.elasticsearch.common.xcontent.XContentBuilder.close(XContentBuilder.java:1015)
          ... 44 more
              }],
    "type": "illegal_argument_exception",
    "reason": "Values less than -1 bytes are not supported: -4b",
    "stack_trace": java.lang.IllegalArgumentException: Values less than -1 bytes are not supported: -4b
        at org.elasticsearch.common.unit.ByteSizeValue.<init>(ByteSizeValue.java:79)
        at org.elasticsearch.common.unit.ByteSizeValue.<init>(ByteSizeValue.java:74)
        at org.elasticsearch.index.cache.query.QueryCacheStats.getMemorySize(QueryCacheStats.java:73)
        at org.elasticsearch.index.cache.query.QueryCacheStats.toXContent(QueryCacheStats.java:130)
        at org.elasticsearch.action.admin.indices.stats.CommonStats.toXContent(CommonStats.java:510)
        at org.elasticsearch.indices.NodeIndicesStats.toXContent(NodeIndicesStats.java:202)
        at org.elasticsearch.action.admin.cluster.node.stats.NodeStats.toXContent(NodeStats.java:324)
        at org.elasticsearch.action.admin.cluster.node.stats.NodesStatsResponse.toXContent(NodesStatsResponse.java:61)
        at org.elasticsearch.rest.action.RestActions.nodesResponse(RestActions.java:184)
        at org.elasticsearch.rest.action.RestActions$NodesResponseRestListener.buildResponse(RestActions.java:237)
        at org.elasticsearch.rest.action.RestActions$NodesResponseRestListener.buildResponse(RestActions.java:228)
        at org.elasticsearch.rest.action.RestBuilderListener.buildResponse(RestBuilderListener.java:38)
        at org.elasticsearch.rest.action.RestResponseListener.processResponse(RestResponseListener.java:37)
        at org.elasticsearch.rest.action.RestActionListener.onResponse(RestActionListener.java:47)
        at org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:89)
        at org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:83)
        at org.elasticsearch.action.ActionRunnable.lambda$supply$0(ActionRunnable.java:58)
        at org.elasticsearch.action.ActionRunnable$2.doRun(ActionRunnable.java:73)
        at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
        at org.elasticsearch.common.util.concurrent.EsExecutors$DirectExecutorService.execute(EsExecutors.java:224)
        at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.finishHim(TransportNodesAction.java:263)
        at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.onOperation(TransportNodesAction.java:248)
        at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.access$000(TransportNodesAction.java:177)
        at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:226)
        at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:218)
        at org.elasticsearch.transport.TransportService$6.handleResponse(TransportService.java:634)
        at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleResponse(TransportService.java:1171)
        at org.elasticsearch.transport.InboundHandler.doHandleResponse(InboundHandler.java:253)
        at org.elasticsearch.transport.InboundHandler.handleResponse(InboundHandler.java:245)
        at org.elasticsearch.transport.InboundHandler.messageReceived(InboundHandler.java:133)
        at org.elasticsearch.transport.InboundHandler.inboundMessage(InboundHandler.java:89)
        at org.elasticsearch.transport.TcpTransport.inboundMessage(TcpTransport.java:700)
        at org.elasticsearch.transport.InboundPipeline.forwardFragments(InboundPipeline.java:142)
        at org.elasticsearch.transport.InboundPipeline.doHandleBytes(InboundPipeline.java:117)
        at org.elasticsearch.transport.InboundPipeline.handleBytes(InboundPipeline.java:82)
        at org.elasticsearch.transport.netty4.Netty4MessageChannelHandler.channelRead(Netty4MessageChannelHandler.java:74)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:271)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:615)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:578)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at java.base/java.lang.Thread.run(Thread.java:832)
        Suppressed: java.lang.IllegalStateException: Failed to close the XContentBuilder
        at org.elasticsearch.common.xcontent.XContentBuilder.close(XContentBuilder.java:1017)
        at org.elasticsearch.rest.action.RestBuilderListener.buildResponse(RestBuilderListener.java:37)
        ... 43 more
        Caused by: java.io.IOException: Unclosed object or array found
        at org.elasticsearch.common.xcontent.json.JsonXContentGenerator.close(JsonXContentGenerator.java:456)
        at org.elasticsearch.common.xcontent.XContentBuilder.close(XContentBuilder.java:1015)
        ... 44 more
        
    "suppressed": [{
 "type": "illegal_state_exception",
 "reason": "Failed to close the XContentBuilder",
 "caused_by": {
   "type": "i_o_exception",
   "reason": "Unclosed object or array found",
   "stack_trace": java.io.IOException: Unclosed object or array found
      at org.elasticsearch.common.xcontent.json.JsonXContentGenerator.close(JsonXContentGenerator.java:456)
      at org.elasticsearch.common.xcontent.XContentBuilder.close(XContentBuilder.java:1015)
      at org.elasticsearch.rest.action.RestBuilderListener.buildResponse(RestBuilderListener.java:37)
      at org.elasticsearch.rest.action.RestResponseListener.processResponse(RestResponseListener.java:37)
      at org.elasticsearch.rest.action.RestActionListener.onResponse(RestActionListener.java:47)
      at org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:89)
      at org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:83)
      at org.elasticsearch.action.ActionRunnable.lambda$supply$0(ActionRunnable.java:58)
      at org.elasticsearch.action.ActionRunnable$2.doRun(ActionRunnable.java:73)
      at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
      at org.elasticsearch.common.util.concurrent.EsExecutors$DirectExecutorService.execute(EsExecutors.java:224)
      at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.finishHim(TransportNodesAction.java:263)
      at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.onOperation(TransportNodesAction.java:248)
      at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.access$000(TransportNodesAction.java:177)
      at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:226)
      at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:218)
      at org.elasticsearch.transport.TransportService$6.handleResponse(TransportService.java:634)
      at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleResponse(TransportService.java:1171)
      at org.elasticsearch.transport.InboundHandler.doHandleResponse(InboundHandler.java:253)
      at org.elasticsearch.transport.InboundHandler.handleResponse(InboundHandler.java:245)
      at org.elasticsearch.transport.InboundHandler.messageReceived(InboundHandler.java:133)
      at org.elasticsearch.transport.InboundHandler.inboundMessage(InboundHandler.java:89)
      at org.elasticsearch.transport.TcpTransport.inboundMessage(TcpTransport.java:700)
      at org.elasticsearch.transport.InboundPipeline.forwardFragments(InboundPipeline.java:142)
      at org.elasticsearch.transport.InboundPipeline.doHandleBytes(InboundPipeline.java:117)
      at org.elasticsearch.transport.InboundPipeline.handleBytes(InboundPipeline.java:82)
      at org.elasticsearch.transport.netty4.Netty4MessageChannelHandler.channelRead(Netty4MessageChannelHandler.java:74)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
      at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
      at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:271)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
      at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
      at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
      at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
      at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
      at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
      at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:615)
      at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:578)
      at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
      at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
      at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
      at java.base/java.lang.Thread.run(Thread.java:832)
      },
 "stack_trace": java.lang.IllegalStateException: Failed to close the XContentBuilder
    at org.elasticsearch.common.xcontent.XContentBuilder.close(XContentBuilder.java:1017)
    at org.elasticsearch.rest.action.RestBuilderListener.buildResponse(RestBuilderListener.java:37)
    at org.elasticsearch.rest.action.RestResponseListener.processResponse(RestResponseListener.java:37)
    at org.elasticsearch.rest.action.RestActionListener.onResponse(RestActionListener.java:47)
    at org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:89)
    at org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:83)
    at org.elasticsearch.action.ActionRunnable.lambda$supply$0(ActionRunnable.java:58)
    at org.elasticsearch.action.ActionRunnable$2.doRun(ActionRunnable.java:73)
    at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
    at org.elasticsearch.common.util.concurrent.EsExecutors$DirectExecutorService.execute(EsExecutors.java:224)
    at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.finishHim(TransportNodesAction.java:263)
    at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.onOperation(TransportNodesAction.java:248)
    at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction.access$000(TransportNodesAction.java:177)
    at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:226)
    at org.elasticsearch.action.support.nodes.TransportNodesAction$AsyncAction$1.handleResponse(TransportNodesAction.java:218)
    at org.elasticsearch.transport.TransportService$6.handleResponse(TransportService.java:634)
    at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleResponse(TransportService.java:1171)
    at org.elasticsearch.transport.InboundHandler.doHandleResponse(InboundHandler.java:253)
    at org.elasticsearch.transport.InboundHandler.handleResponse(InboundHandler.java:245)
    at org.elasticsearch.transport.InboundHandler.messageReceived(InboundHandler.java:133)
    at org.elasticsearch.transport.InboundHandler.inboundMessage(InboundHandler.java:89)
    at org.elasticsearch.transport.TcpTransport.inboundMessage(TcpTransport.java:700)
    at org.elasticsearch.transport.InboundPipeline.forwardFragments(InboundPipeline.java:142)
    at org.elasticsearch.transport.InboundPipeline.doHandleBytes(InboundPipeline.java:117)
    at org.elasticsearch.transport.InboundPipeline.handleBytes(InboundPipeline.java:82)
    at org.elasticsearch.transport.netty4.Netty4MessageChannelHandler.channelRead(Netty4MessageChannelHandler.java:74)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:271)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:615)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:578)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at java.base/java.lang.Thread.run(Thread.java:832)
    used by: java.io.IOException: Unclosed object or array found
    at org.elasticsearch.common.xcontent.json.JsonXContentGenerator.close(JsonXContentGenerator.java:456)
    at org.elasticsearch.common.xcontent.XContentBuilder.close(XContentBuilder.java:1015)
    ... 44 more
        }]
  },
  "status": 400
}

[RicardoGralhoz]

Is there anything I can do to help, like collecting more detailed information?

It seems reproducible on my environment. I'm doing intensive time series bulk indexing, occasional delete of expired indices and create of new ones, once a threshold is reached (which perhaps is internally moving shards around). These should be the guilty parties on using the heap. Other lighter operations are: querying for a couple of health stats (every 10 min or so), querying for user prefs (small index), etc. When the issue happened, there was no GUI query involved.

Here some CPU/RAM stats a few seconds after the error first occurred (note elasticsearch is using 20GB of memory):

CPU Check
  us:100.8 ni:0 sy:11.2 id:673.3 wa:6.2 hi:0 si:0.6 st:0.8 

CPU/RAM Check
  elasticsearch:0.3%/20833M  
  node-es-app:0.7%/280M
  node-gui-app:0%/136M
  node-kafka-consumer-app:0.3%/222M

The first error timestamp is Dec 25 2020 14:36:29.945 which is 2020-12-25T22:36:29.945+0000:

[2020-12-25T22:35:27.802+0000][17629][gc,task     ] GC(5572) Using 8 workers of 8 for evacuation
[2020-12-25T22:35:27.802+0000][17629][gc,age      ] GC(5572) Desired survivor size 645922816 bytes, new threshold 15 (max threshold 15)
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) Age table with threshold 15 (max threshold 15)
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age   1:   96866720 bytes,   96866720 total 
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age   2:     875688 bytes,   97742408 total 
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age   3:    1148584 bytes,   98890992 total 
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age   4:    1228376 bytes,  100119368 total 
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age   5:     671064 bytes,  100790432 total 
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age   6:    1317520 bytes,  102107952 total 
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age   7:    2431152 bytes,  104539104 total 
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age   8:    1062832 bytes,  105601936 total 
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age   9:    1093856 bytes,  106695792 total 
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age  10:     931104 bytes,  107626896 total 
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age  11:     960808 bytes,  108587704 total 
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age  12:    1379720 bytes,  109967424 total 
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age  13:    1897664 bytes,  111865088 total 
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age  14:    1075400 bytes,  112940488 total 
[2020-12-25T22:35:27.845+0000][17629][gc,age      ] GC(5572) - age  15:    1100864 bytes,  114041352 total 
[2020-12-25T22:35:27.845+0000][17629][gc,phases   ] GC(5572)   Pre Evacuate Collection Set: 0.5ms 
[2020-12-25T22:35:27.845+0000][17629][gc,phases   ] GC(5572)   Merge Heap Roots: 0.4ms 
[2020-12-25T22:35:27.845+0000][17629][gc,phases   ] GC(5572)   Evacuate Collection Set: 34.4ms
[2020-12-25T22:35:27.845+0000][17629][gc,phases   ] GC(5572)   Post Evacuate Collection Set: 7.1ms 
[2020-12-25T22:35:27.845+0000][17629][gc,phases   ] GC(5572)   Other: 0.5ms 
[2020-12-25T22:35:27.845+0000][17629][gc,heap     ] GC(5572) Eden regions: 1217->0(1213)
[2020-12-25T22:35:27.845+0000][17629][gc,heap     ] GC(5572) Survivor regions: 11->15(154)
[2020-12-25T22:35:27.845+0000][17629][gc,heap     ] GC(5572) Old regions: 120->121
[2020-12-25T22:35:27.845+0000][17629][gc,heap     ] GC(5572) Archive regions: 2->2
[2020-12-25T22:35:27.845+0000][17629][gc,heap     ] GC(5572) Humongous regions: 8->8
[2020-12-25T22:35:27.845+0000][17629][gc,metaspace] GC(5572) Metaspace: 81817K(84304K)->81817K(84304K) NonClass: 72150K(73936K)->72150K(73936K) Class: 9667K(10368K)->9667K(10368K)
[2020-12-25T22:35:27.845+0000][17629][gc          ] GC(5572) Pause Young (Normal) (G1 Evacuation Pause) 10855M->1147M(16384M) 43.178ms
[2020-12-25T22:35:27.845+0000][17629][gc,cpu      ] GC(5572) User=0.09s Sys=0.00s Real=0.05s
[2020-12-25T22:35:27.845+0000][17629][safepoint   ] Safepoint "G1CollectForAllocation", Time since last: 187299620267 ns, Reaching safepoint: 368638 ns, At safepoint: 43323743 ns, Total: 43692381 ns
[2020-12-25T22:36:29.858+0000][17629][safepoint   ] Safepoint "Cleanup", Time since last: 62012215944 ns, Reaching safepoint: 181759 ns, At safepoint: 15241 ns, Total: 197000 ns
[2020-12-25T22:36:30.858+0000][17629][safepoint   ] Safepoint "Cleanup", Time since last: 1000309566 ns, Reaching safepoint: 179210 ns, At safepoint: 10574 ns, Total: 189784 ns
[2020-12-25T22:36:53.862+0000][17629][safepoint   ] Safepoint "Cleanup", Time since last: 23003486317 ns, Reaching safepoint: 199146 ns, At safepoint: 9706 ns, Total: 208852 ns
[2020-12-25T22:37:04.864+0000][17629][safepoint   ] Safepoint "Cleanup", Time since last: 11001632988 ns, Reaching safepoint: 329561 ns, At safepoint: 22201 ns, Total: 351762 ns
[2020-12-25T22:38:28.878+0000][17629][safepoint   ] Safepoint "Cleanup", Time since last: 84013263412 ns, Reaching safepoint: 352420 ns, At safepoint: 15756 ns, Total: 368176 ns

[danhermann]

Is there anything I can do to help, like collecting more detailed information?

It seems reproducible on my environment. I'm doing intensive time series bulk indexing, occasional delete of expired indices and create of new ones, once a threshold is reached (which perhaps is internally moving shards around). These should be the guilty parties on using the heap. Other lighter operations are: querying for a couple of health stats (every 10 min or so), querying for user prefs (small index), etc. When the issue happened, there was no GUI query involved.

@RicardoGralhoz, thank you for the offer of more detailed information. I think the most likely explanation for this problem is a bug in the code that tracks the query cache size which is likely to be tricky to track down. Two items that might be helpful are a description of your reproduction scenario which may enable us to reproduce it locally. A second option might be adding debug logging in a future release that you could enable in your environment that might help us locate the source of the problem.

[RicardoGralhoz]

@RicardoGralhoz, [...] Two items that might be helpful are a description of your reproduction scenario which may enable us to reproduce it locally. A second option might be adding debug logging in a future release that you could enable in your environment that might help us locate the source of the problem.

Yeah, a more specific debug logging may be a good alternative to try. I don't know the exact steps to reproduce it, since it seems related to the dynamic usage of the cache and it may be reached on certain conditions. What I know I have posted here and you can add to it details from these 3 posts:

1. Help with (...) Values less than -1 bytes are not supported
2. /_cluster/stats when it worked
3. details about the Bulk API

[danhermann]

@RicardoGralhoz, I've added debug logging in #67444 that should provide some diagnostic info at the point that a negative value in query cache stats is first detected. It will be included in the next release of Elasticsearch.

[RicardoGralhoz]

Thanks @danhermann ! I assume this extra logging would be available on error_trace=true, right? I see that the PR is targeted to v. >= 7.11 and it has a backport pending label. Does it mean that it may be ported to v7.10.x? I'm not sure I will be able to try it on v7.11+ due to the recent changes in licensing 🤔 .