Slow log fails after upgrading from 6.8.3 to 7.4.0

[naag]

Elasticsearch version: Version: 7.4.0, Build: default/tar/22e1767283e61a198cb4db791ea66e3f11ab9910/2019-09-27T08:36:48.569419Z, JVM: 11.0.4

Plugins installed: [repository-s3]

JVM version: openjdk version "11.0.4" 2019-07-16
OpenJDK Runtime Environment (build 11.0.4+11-post-Debian-1bpo91)
OpenJDK 64-Bit Server VM (build 11.0.4+11-post-Debian-1bpo91, mixed mode, sharing)

OS version: Linux es-node01 4.9.0-9-amd64 #1 SMP Debian 4.9.168-1+deb9u4 (2019-07-19) x86_64 GNU/Linux

Description of the problem including expected versus actual behavior:

We're seeing the following log message in our Elasticsearch logs after upgrading from ES 6.8.3 to 7.4.0:

[2019-10-22T16:59:24,044][WARN ][o.e.i.s.IndexShard       ] [es-node01] [news-2019.06][2] onQueryPhase listener [org.elasticsearch.index.SearchSlowLog@4041c06f] failed
java.lang.ArrayIndexOutOfBoundsException: arraycopy: last destination index 3000 out of bounds for byte[2064]
	at java.lang.System.arraycopy(Native Method) ~[?:?]
	at com.fasterxml.jackson.core.util.ByteArrayBuilder.toByteArray(ByteArrayBuilder.java:128) ~[jackson-core-2.8.11.jar:2.8.11]
	at com.fasterxml.jackson.core.util.ByteArrayBuilder.completeAndCoalesce(ByteArrayBuilder.java:179) ~[jackson-core-2.8.11.jar:2.8.11]
	at com.fasterxml.jackson.core.io.JsonStringEncoder.quoteAsUTF8(JsonStringEncoder.java:283) ~[jackson-core-2.8.11.jar:2.8.11]
	at org.elasticsearch.common.logging.ESLogMessage.escapeJson(ESLogMessage.java:49) ~[elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.index.SearchSlowLog$SearchSlowLogMessage.prepareMap(SearchSlowLog.java:180) ~[elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.index.SearchSlowLog$SearchSlowLogMessage.<init>(SearchSlowLog.java:159) ~[elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.index.SearchSlowLog.onQueryPhase(SearchSlowLog.java:135) ~[elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.index.shard.SearchOperationListener$CompositeListener.onQueryPhase(SearchOperationListener.java:155) [elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.search.SearchService$SearchOperationListenerExecutor.close(SearchService.java:1130) [elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:362) [elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.search.SearchService.lambda$executeQueryPhase$1(SearchService.java:340) [elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.action.ActionListener.lambda$map$2(ActionListener.java:145) [elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:62) [elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.search.SearchService.lambda$rewriteShardRequest$7(SearchService.java:1043) [elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.action.ActionRunnable$1.doRun(ActionRunnable.java:45) [elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:44) [elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:773) [elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-7.4.0.jar:7.4.0]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:834) [?:?]

At least some slow logs are still being logged, so it doesn't seem entirely broken, but still we're worried about the errors.

Steps to reproduce:

Unknown unfortunately, since we cannot isolate the traffic that's causing the warnings to be logged.

Thanks for your support :-)

[jimczi]

That's indeed a bug, thanks for reporting @naag. I opened #48363 to fix the AIOOBE but any deployment of 7.4.0 that enables search slow log is impacted by this bug.

[elasticmachine]

Pinging @elastic/es-core-infra (:Core/Infra/Logging)

[naag]

Thanks @jimczi for the very fast reaction! Do you think that we can still use slow log then (at least partially) or will it cause client visible errors?

[jimczi]

Do you think that we can still use slow log then (at least partially) or will it cause client visible errors?

I don't think you should activate the slow logs in 7.4.0, this bug will create random exceptions on logged queries so it should be avoided until we provide a fix.