elastic/elasticsearch

Null pointer when using bulk inserts

nfroidure opened this issue · 6 comments

Elasticsearch version:
5.4.2 using the Docker image:

docker run -p 9200:9200 -e "http.host=0.0.0.0" -e "transport.host=127.0.0.1" docker.elastic.co/elasticsearch/elasticsearch:5.4.2

Plugins installed: []

JVM version (java -version):
The one used by the docker image
OS version (uname -a if on a Unix-like system):
Docker on Ubuntu
Description of the problem including expected versus actual behavior:
Having null pointer exception:

java.lang.NullPointerException: null
	at org.elasticsearch.action.bulk.BulkRequest.add(BulkRequest.java:318) ~[elasticsearch-5.4.2.jar:5.4.2]
	at org.elasticsearch.rest.action.document.RestBulkAction.prepareRequest(RestBulkAction.java:89) ~[elasticsearch-5.4.2.jar:5.4.2]
	at org.elasticsearch.rest.BaseRestHandler.handleRequest(BaseRestHandler.java:64) ~[elasticsearch-5.4.2.jar:5.4.2]
	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.2.jar:5.4.2]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$finishAuthentication$20(AuthenticationService.java:424) ~[?:?]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.finishAuthentication(AuthenticationService.java:433) ~[?:?]
	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.2.jar:5.4.2]
	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.2.jar:5.4.2]
	at org.elasticsearch.xpack.security.authc.support.CachingUsernamePasswordRealm.authenticateWithCache(CachingUsernamePasswordRealm.java:117) ~[x-pack-5.4.2.jar:5.4.2]
	at org.elasticsearch.xpack.security.authc.support.CachingUsernamePasswordRealm.authenticate(CachingUsernamePasswordRealm.java:92) ~[x-pack-5.4.2.jar:5.4.2]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$consumeToken$10(AuthenticationService.java:264) ~[x-pack-5.4.2.jar:5.4.2]
	at org.elasticsearch.xpack.common.IteratingActionListener.run(IteratingActionListener.java:93) ~[x-pack-5.4.2.jar:5.4.2]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.consumeToken(AuthenticationService.java:288) ~[x-pack-5.4.2.jar:5.4.2]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$extractToken$6(AuthenticationService.java:239) ~[x-pack-5.4.2.jar:5.4.2]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.extractToken(AuthenticationService.java:247) ~[x-pack-5.4.2.jar:5.4.2]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$authenticateAsync$0(AuthenticationService.java:194) ~[x-pack-5.4.2.jar:5.4.2]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$lookForExistingAuthentication$2(AuthenticationService.java:212) ~[x-pack-5.4.2.jar:5.4.2]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lookForExistingAuthentication(AuthenticationService.java:224) [x-pack-5.4.2.jar:5.4.2]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.authenticateAsync(AuthenticationService.java:190) [x-pack-5.4.2.jar:5.4.2]
	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.access$000(AuthenticationService.java:147) [x-pack-5.4.2.jar:5.4.2]
	at org.elasticsearch.xpack.security.authc.AuthenticationService.authenticate(AuthenticationService.java:100) [x-pack-5.4.2.jar:5.4.2]
	at org.elasticsearch.xpack.security.rest.SecurityRestFilter.handleRequest(SecurityRestFilter.java:78) [x-pack-5.4.2.jar:5.4.2]
	at org.elasticsearch.rest.RestController.dispatchRequest(RestController.java:260) [elasticsearch-5.4.2.jar:5.4.2]
	at org.elasticsearch.rest.RestController.dispatchRequest(RestController.java:199) [elasticsearch-5.4.2.jar:5.4.2]
	at org.elasticsearch.http.netty4.Netty4HttpServerTransport.dispatchRequest(Netty4HttpServerTransport.java:505) [transport-netty4-5.4.2.jar:5.4.2]
	at org.elasticsearch.http.netty4.Netty4HttpRequestHandler.channelRead0(Netty4HttpRequestHandler.java:72) [transport-netty4-5.4.2.jar:5.4.2]
	at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at org.elasticsearch.http.netty4.pipelining.HttpPipeliningHandler.channelRead(HttpPipeliningHandler.java:63) [transport-netty4-5.4.2.jar:5.4.2]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111) [netty-codec-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:310) [netty-codec-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:284) [netty-codec-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:134) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:644) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:544) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:498) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:458) [netty-transport-4.1.11.Final.jar:4.1.11.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858) [netty-common-4.1.11.Final.jar:4.1.11.Final]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_131]

Steps to reproduce:
Use the NodeJS client to bulk add:

{
  "body": [
    {
      "update": {
        "_index": "sencrop-measures",
        "_type": "measures",
        "_id": "028D-SAT-1421148266000"
      }
    },
    {
      "doc": {
        "type": "SAT",
        "value": 6,
        "time": 1421148266000,
        "timeFrame": {
          "gt": 1421148266000,
          "lte": 1421148266000
        },
        "verified": false,
        "device": "028D",
        "usersIds": [],
        "organisationsIds": [],
        "signal": 1969,
        "udm": 22,
        "id": "RADAR69"
      }
    },
    {
      "update": {
        "_index": "sencrop-measures",
        "_type": "measures",
        "_id": "028D-PRECISION-1421148266000"
      }
    },
    {
      "doc": {
        "type": "PRECISION",
        "value": 1,
        "time": 1421148266000,
        "timeFrame": {
          "gt": 1421148266000,
          "lte": 1421148266000
        },
        "verified": false,
        "device": "028D",
        "usersIds": [],
        "organisationsIds": [],
        "signal": 1969,
        "udm": 22,
        "id": "RADAR69"
      }
    },
    {
      "update": {
        "_index": "sencrop-measures",
        "_type": "measures",
        "_id": "028D-LNG-1421148266000"
      }
    },
    {
      "doc": {
        "type": "LNG",
        "value": 3.0434833333333335,
        "time": 1421148266000,
        "timeFrame": {
          "gt": 1421148266000,
          "lte": 1421148266000
        },
        "verified": false,
        "device": "028D",
        "usersIds": [],
        "organisationsIds": [],
        "signal": 1969,
        "udm": 22,
        "id": "RADAR69"
      }
    },
    {
      "update": {
        "_index": "sencrop-measures",
        "_type": "measures",
        "_id": "028D-LAT-1421148266000"
      }
    },
    {
      "doc": {
        "type": "LAT",
        "value": 50.65155,
        "time": 1421148266000,
        "timeFrame": {
          "gt": 1421148266000,
          "lte": 1421148266000
        },
        "verified": false,
        "device": "028D",
        "usersIds": [],
        "organisationsIds": [],
        "signal": 1969,
        "udm": 22,
        "id": "RADAR69"
      }
    },
    {
      "update": {
        "_index": "sencrop-measures",
        "_type": "measures",
        "_id": "028D-ALT-1421148266000"
      }
    },
    {
      "doc": {
        "type": "ALT",
        "value": 67,
        "time": 1421148266000,
        "timeFrame": {
          "gt": 1421148266000,
          "lte": 1421148266000
        },
        "verified": false,
        "device": "028D",
        "usersIds": [],
        "organisationsIds": [],
        "signal": 1969,
        "udm": 22,
        "id": "RADAR69"
      }
    }
  ]
}

To the following mappings:

{
  "_all": {
    "enabled": false
  },
  "properties": {
    "type": {
      "type": "keyword"
    },
    "device": {
      "type": "keyword"
    },
    "name": {
      "type": "text"
    },
    "usersIds": {
      "type": "integer"
    },
    "organisationsIds": {
      "type": "integer"
    },
    "value": {
      "type": "integer"
    },
    "signal": {
      "type": "integer"
    },
    "udm": {
      "type": "integer"
    },
    "location": {
      "type": "geo_point"
    },
    "time": {
      "type": "date",
      "format": "epoch_millis"
    },
    "timeFrame": {
      "type": "date_range",
      "format": "epoch_millis"
    }
  }
}

I still use it locally for now so i can provide you the credentials I use since the stack trace seems related to the basic authentication.:


const elasticsearch = require('elasticsearch');
const c = new elasticsearch.Client({
    protocol: 'http',
    host: '127.0.0.1:9200',
    httpAuth: 'elastic:changeme',
    apiVersion: '5.4',
  });

Provide logs (if relevant):

tlrx commented

The error refers to a line where the content type of the request is used. It looks like the NodeJS client does not provide the Content-Type header required for executing the bulk requests. I think this is configurable but I'm not sure how.

I suggest that you create an issue in the https://github.com/elastic/elasticsearch-js/issues/ repository where a maintainer will know for sure is the content-type is correctly set by the client.

Note that bulk requests require the Content-Type: "application/x-ndjson" header.

FYI, the problem does not sit in the NodeJS connector since I found out that the real origin of the issue was that I was doing 2 bulk inserts in parallel.

That said, I think that a null pointer exception, whatever caused it, should be considered a programming error, not a non-issue.

tlrx commented

FYI, the problem does not sit in the NodeJS connector since I found out that the real origin of the issue was that I was doing 2 bulk inserts in parallel.

Multiple bulks requests can be concurrently executed on the elasticsearch side. You were executing 3 bulk requests in parallel using the NodeJS connector, and now you changed that the error disappears? It looks like the cause is located on the client-side, any chance to grab the HTTP requests that are executed?

That said, I think that a null pointer exception, whatever caused it, should be considered a programming error, not a non-issue.

I agree, I've been too quick on closing this issue, sorry for that.

No problem, i reverted my change an i can constantly reproduce the issue.

If traced HTTP calls with nock and I think the issue is due to the fact that there is no request body at all.

So, for ElasticSearch server, just testing for request body existence and throwing a proper error should avoid having null pointer exceptions.

There is no problem with the NodeJS client since I just figured out that the second bulk insert i made was indeed empty, this is why joining the 2 bulk inserts solved my issue.

nock('http://127.0.0.1:9200', {"encodedQueryParams":true})
  .post('/_bulk')
  .reply(500, {"error":{"root_cause":[{"type":"null_pointer_exception","reason":null}],"type":"null_pointer_exception","reason":null},"status":500}, [ 'content-type',
  'application/json; charset=UTF-8',
  'content-length',
  '133' ]);

<<<<<<-- cut here -->>>>>>

tlrx commented

@nfroidure Thanks for digging this one!

I think you hit #24701 that is fixed in #23497 and will be released in 5.5.0.

Thank you for building such a good product ;).