Cannot optimize index due to NPE

[tnunes]

Elasticsearch version: 5.4.0

Plugins installed: [ingest-geoip, ingest-user-agent, x-pack]

JVM version:
java version "1.8.0_74"
Java(TM) SE Runtime Environment (build 1.8.0_74-b02)
Java HotSpot(TM) 64-Bit Server VM (build 25.74-b02, mixed mode)

OS version:
Darwin MacOS 16.6.0 Darwin Kernel Version 16.6.0: Fri Apr 14 16:21:16 PDT 2017; root:xnu-3789.60.24~6/RELEASE_X86_64 x86_64

Description of the problem including expected versus actual behavior:
Cannot optimize index due to NPE.

Tried index recovery, which ran successfully, but still cannot optimize index.

Steps to reproduce:

POST elasticsearch:9200/catalog-dev/_optimize

{
    "error": {
        "reason": null,
        "root_cause": [
            {
                "reason": null,
                "type": "null_pointer_exception"
            }
        ],
        "type": "null_pointer_exception"
    },
    "status": 500
}

Provide logs (if relevant):

[2017-06-01T14:39:02,579][WARN ][r.suppressed             ] path: /catalog-dev/_optimize, params: {index=catalog-dev, type=_optimize}
java.lang.NullPointerException: null
	at java.util.Objects.requireNonNull(Objects.java:203) ~[?:1.8.0_74]
	at org.elasticsearch.action.index.IndexRequest.source(IndexRequest.java:464) ~[elasticsearch-5.4.0.jar:5.4.0]
	at org.elasticsearch.rest.action.document.RestIndexAction.prepareRequest(RestIndexAction.java:75) ~[elasticsearch-5.4.0.jar:5.4.0]
	at org.elasticsearch.rest.BaseRestHandler.handleRequest(BaseRestHandler.java:64) ~[elasticsearch-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.rest.SecurityRestFilter.lambda$handleRequest$0(SecurityRestFilter.java:81) ~[?:?]
	at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:59) ~[elasticsearch-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$finishAuthentication$20(AuthenticationService.java:417) ~[?:?]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.finishAuthentication(AuthenticationService.java:426) ~[?:?]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.consumeUser(AuthenticationService.java:360) ~[?:?]
	at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:59) ~[elasticsearch-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.common.IteratingActionListener.onResponse(IteratingActionListener.java:114) ~[?:?]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$null$8(AuthenticationService.java:272) ~[?:?]
	at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:59) ~[elasticsearch-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.authc.support.CachingUsernamePasswordRealm.authenticateWithCache(CachingUsernamePasswordRealm.java:117) ~[x-pack-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.authc.support.CachingUsernamePasswordRealm.authenticate(CachingUsernamePasswordRealm.java:92) ~[x-pack-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$consumeToken$10(AuthenticationService.java:264) ~[x-pack-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.common.IteratingActionListener.run(IteratingActionListener.java:93) ~[x-pack-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.consumeToken(AuthenticationService.java:288) ~[x-pack-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$extractToken$6(AuthenticationService.java:239) ~[x-pack-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.extractToken(AuthenticationService.java:247) ~[x-pack-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$authenticateAsync$0(AuthenticationService.java:194) ~[x-pack-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$lookForExistingAuthentication$2(AuthenticationService.java:212) ~[x-pack-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lookForExistingAuthentication(AuthenticationService.java:224) [x-pack-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.authenticateAsync(AuthenticationService.java:190) [x-pack-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.access$000(AuthenticationService.java:147) [x-pack-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.authc.AuthenticationService.authenticate(AuthenticationService.java:100) [x-pack-5.4.0.jar:5.4.0]
	at org.elasticsearch.xpack.security.rest.SecurityRestFilter.handleRequest(SecurityRestFilter.java:78) [x-pack-5.4.0.jar:5.4.0]
	at org.elasticsearch.rest.RestController.dispatchRequest(RestController.java:260) [elasticsearch-5.4.0.jar:5.4.0]
	at org.elasticsearch.rest.RestController.dispatchRequest(RestController.java:199) [elasticsearch-5.4.0.jar:5.4.0]
	at org.elasticsearch.http.netty4.Netty4HttpServerTransport.dispatchRequest(Netty4HttpServerTransport.java:504) [transport-netty4-5.4.0.jar:5.4.0]
	at org.elasticsearch.http.netty4.Netty4HttpRequestHandler.channelRead0(Netty4HttpRequestHandler.java:72) [transport-netty4-5.4.0.jar:5.4.0]
	at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at org.elasticsearch.http.netty4.pipelining.HttpPipeliningHandler.channelRead(HttpPipeliningHandler.java:63) [transport-netty4-5.4.0.jar:5.4.0]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111) [netty-codec-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293) [netty-codec-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267) [netty-codec-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:134) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:624) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:524) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:478) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:438) [netty-transport-4.1.9.Final.jar:4.1.9.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858) [netty-common-4.1.9.Final.jar:4.1.9.Final]
	at java.lang.Thread.run(Thread.java:745) [?:1.8.0_74]

Index recovery response:

GET elasticsearch:9200/catalog-dev/_recovery?human

{
    "catalog-dev": {
        "shards": [
            {
                "id": 2,
                "index": {
                    "files": {
                        "percent": "100.0%",
                        "recovered": 0,
                        "reused": 42,
                        "total": 42
                    },
                    "size": {
                        "percent": "100.0%",
                        "recovered": "0b",
                        "recovered_in_bytes": 0,
                        "reused": "18.1mb",
                        "reused_in_bytes": 19018114,
                        "total": "18.1mb",
                        "total_in_bytes": 19018114
                    },
                    "source_throttle_time": "-1",
                    "source_throttle_time_in_millis": 0,
                    "target_throttle_time": "-1",
                    "target_throttle_time_in_millis": 0,
                    "total_time": "4ms",
                    "total_time_in_millis": 4
                },
                "primary": true,
                "source": {},
                "stage": "DONE",
                "start_time": "2017-06-01T13:58:08.103Z",
                "start_time_in_millis": 1496325488103,
                "stop_time": "2017-06-01T13:58:08.160Z",
                "stop_time_in_millis": 1496325488160,
                "target": {
                    "host": "127.0.0.1",
                    "id": "umqYf1ePSX2crD-_LEZQhw",
                    "ip": "127.0.0.1",
                    "name": "umqYf1e",
                    "transport_address": "127.0.0.1:9300"
                },
                "total_time": "57ms",
                "total_time_in_millis": 57,
                "translog": {
                    "percent": "100.0%",
                    "recovered": 0,
                    "total": 0,
                    "total_on_start": 0,
                    "total_time": "47ms",
                    "total_time_in_millis": 47
                },
                "type": "EXISTING_STORE",
                "verify_index": {
                    "check_index_time": "0s",
                    "check_index_time_in_millis": 0,
                    "total_time": "0s",
                    "total_time_in_millis": 0
                }
            },
            {
                "id": 3,
                "index": {
                    "files": {
                        "percent": "100.0%",
                        "recovered": 0,
                        "reused": 21,
                        "total": 21
                    },
                    "size": {
                        "percent": "100.0%",
                        "recovered": "0b",
                        "recovered_in_bytes": 0,
                        "reused": "17.7mb",
                        "reused_in_bytes": 18586448,
                        "total": "17.7mb",
                        "total_in_bytes": 18586448
                    },
                    "source_throttle_time": "-1",
                    "source_throttle_time_in_millis": 0,
                    "target_throttle_time": "-1",
                    "target_throttle_time_in_millis": 0,
                    "total_time": "6ms",
                    "total_time_in_millis": 6
                },
                "primary": true,
                "source": {},
                "stage": "DONE",
                "start_time": "2017-06-01T13:58:08.031Z",
                "start_time_in_millis": 1496325488031,
                "stop_time": "2017-06-01T13:58:08.062Z",
                "stop_time_in_millis": 1496325488062,
                "target": {
                    "host": "127.0.0.1",
                    "id": "umqYf1ePSX2crD-_LEZQhw",
                    "ip": "127.0.0.1",
                    "name": "umqYf1e",
                    "transport_address": "127.0.0.1:9300"
                },
                "total_time": "30ms",
                "total_time_in_millis": 30,
                "translog": {
                    "percent": "100.0%",
                    "recovered": 0,
                    "total": 0,
                    "total_on_start": 0,
                    "total_time": "21ms",
                    "total_time_in_millis": 21
                },
                "type": "EXISTING_STORE",
                "verify_index": {
                    "check_index_time": "0s",
                    "check_index_time_in_millis": 0,
                    "total_time": "0s",
                    "total_time_in_millis": 0
                }
            },
            {
                "id": 4,
                "index": {
                    "files": {
                        "percent": "100.0%",
                        "recovered": 0,
                        "reused": 39,
                        "total": 39
                    },
                    "size": {
                        "percent": "100.0%",
                        "recovered": "0b",
                        "recovered_in_bytes": 0,
                        "reused": "18.3mb",
                        "reused_in_bytes": 19224929,
                        "total": "18.3mb",
                        "total_in_bytes": 19224929
                    },
                    "source_throttle_time": "-1",
                    "source_throttle_time_in_millis": 0,
                    "target_throttle_time": "-1",
                    "target_throttle_time_in_millis": 0,
                    "total_time": "2ms",
                    "total_time_in_millis": 2
                },
                "primary": true,
                "source": {},
                "stage": "DONE",
                "start_time": "2017-06-01T13:58:07.976Z",
                "start_time_in_millis": 1496325487976,
                "stop_time": "2017-06-01T13:58:08.030Z",
                "stop_time_in_millis": 1496325488030,
                "target": {
                    "host": "127.0.0.1",
                    "id": "umqYf1ePSX2crD-_LEZQhw",
                    "ip": "127.0.0.1",
                    "name": "umqYf1e",
                    "transport_address": "127.0.0.1:9300"
                },
                "total_time": "53ms",
                "total_time_in_millis": 53,
                "translog": {
                    "percent": "100.0%",
                    "recovered": 0,
                    "total": 0,
                    "total_on_start": 0,
                    "total_time": "45ms",
                    "total_time_in_millis": 45
                },
                "type": "EXISTING_STORE",
                "verify_index": {
                    "check_index_time": "0s",
                    "check_index_time_in_millis": 0,
                    "total_time": "0s",
                    "total_time_in_millis": 0
                }
            },
            {
                "id": 1,
                "index": {
                    "files": {
                        "percent": "100.0%",
                        "recovered": 0,
                        "reused": 42,
                        "total": 42
                    },
                    "size": {
                        "percent": "100.0%",
                        "recovered": "0b",
                        "recovered_in_bytes": 0,
                        "reused": "18.2mb",
                        "reused_in_bytes": 19176752,
                        "total": "18.2mb",
                        "total_in_bytes": 19176752
                    },
                    "source_throttle_time": "-1",
                    "source_throttle_time_in_millis": 0,
                    "target_throttle_time": "-1",
                    "target_throttle_time_in_millis": 0,
                    "total_time": "4ms",
                    "total_time_in_millis": 4
                },
                "primary": true,
                "source": {},
                "stage": "DONE",
                "start_time": "2017-06-01T13:58:08.034Z",
                "start_time_in_millis": 1496325488034,
                "stop_time": "2017-06-01T13:58:08.099Z",
                "stop_time_in_millis": 1496325488099,
                "target": {
                    "host": "127.0.0.1",
                    "id": "umqYf1ePSX2crD-_LEZQhw",
                    "ip": "127.0.0.1",
                    "name": "umqYf1e",
                    "transport_address": "127.0.0.1:9300"
                },
                "total_time": "64ms",
                "total_time_in_millis": 64,
                "translog": {
                    "percent": "100.0%",
                    "recovered": 0,
                    "total": 0,
                    "total_on_start": 0,
                    "total_time": "56ms",
                    "total_time_in_millis": 56
                },
                "type": "EXISTING_STORE",
                "verify_index": {
                    "check_index_time": "0s",
                    "check_index_time_in_millis": 0,
                    "total_time": "0s",
                    "total_time_in_millis": 0
                }
            },
            {
                "id": 0,
                "index": {
                    "files": {
                        "percent": "100.0%",
                        "recovered": 0,
                        "reused": 29,
                        "total": 29
                    },
                    "size": {
                        "percent": "100.0%",
                        "recovered": "0b",
                        "recovered_in_bytes": 0,
                        "reused": "17.8mb",
                        "reused_in_bytes": 18749353,
                        "total": "17.8mb",
                        "total_in_bytes": 18749353
                    },
                    "source_throttle_time": "-1",
                    "source_throttle_time_in_millis": 0,
                    "target_throttle_time": "-1",
                    "target_throttle_time_in_millis": 0,
                    "total_time": "2ms",
                    "total_time_in_millis": 2
                },
                "primary": true,
                "source": {},
                "stage": "DONE",
                "start_time": "2017-06-01T13:58:07.981Z",
                "start_time_in_millis": 1496325487981,
                "stop_time": "2017-06-01T13:58:08.018Z",
                "stop_time_in_millis": 1496325488018,
                "target": {
                    "host": "127.0.0.1",
                    "id": "umqYf1ePSX2crD-_LEZQhw",
                    "ip": "127.0.0.1",
                    "name": "umqYf1e",
                    "transport_address": "127.0.0.1:9300"
                },
                "total_time": "36ms",
                "total_time_in_millis": 36,
                "translog": {
                    "percent": "100.0%",
                    "recovered": 0,
                    "total": 0,
                    "total_on_start": 0,
                    "total_time": "28ms",
                    "total_time_in_millis": 28
                },
                "type": "EXISTING_STORE",
                "verify_index": {
                    "check_index_time": "0s",
                    "check_index_time_in_millis": 0,
                    "total_time": "0s",
                    "total_time_in_millis": 0
                }
            }
        ]
    }
}

[jasontedor]

It's not _optimize, it's _forcemerge. This is getting parsed as an indexing request against the type _optimize on the index catalog-dev.

[tnunes]

Thank you @jasontedor for the quick reply, was not aware that _optimize got changed to _forcemerge. It's working now!

Would it make sense for ES to return a 400 or 404 for this scenario?
Even though I invoked the wrong route, it seems this NPE should be avoided and ES should not be returning a 500?

[jasontedor]

@tnunes You raise good questions but this is a tricky situation.

Since there is no handler registered for /catalog-dev/_optimize, your request is interpreted as an index request against the index catalog-dev for the type _optimize (by default, types can be created dynamically). The NPE arises from the empty body for an indexing request which is a bug and should be fixed (there's an open PR to address, #23497). Short of registering a handler for /catalog-dev/_optimize that says "go to _forcemerge" (which I do not think we should do), there's nothing else we can do here given these wildcard endpoints.

[tnunes]

It seems that with the fix you mentioned that 500 is gonna become a 400 with a more explicit message, so it should immediately help a user understand it did something wrong, in contrast to being an ES bug that causes it to blow up.

Thank you for the explanation. I guess when #23497 gets merged and released this should not happen anymore.

(BTW, I believe you meant to s/_forcemerge/_optimize/ your comment :) )

[jasontedor]

Yes, I did, sorry for the mistake, thanks for the correction; I've edited it inline. 😄