Intermittent exception using high-level-rest-client. Unable to load a DateTransformer

Elastic Stack Elasticsearch
1

Elastic Search Version: 7.9.2
Client: Java: elasticsearch-rest-high-level-client
We use elastic search on Kubernetes in AWS.
We are noticing these errors sporadically in our server logs. When this happens, all searches to elastic search are failing from the service while elastic search is responsive to queries through curl.

I looked at the code that generates this error and noticed that this happens when the client is unable to load a DateTransformer. This seems to be happen if the XContentElasticsearchExtension cannot be loaded (which seems to provide the DateTransformer) . I cannot explain why this situation would arise.
This in fact seems to be the case. When this happens, I used the following line to print the state of the XContentBuilderExtension,
for (XContentBuilderExtension service : ServiceLoader.load(XContentBuilderExtension.class)); This loop finds no XContentBuilderExtension while the [org.elasticsearch.common.xcontent.XContentElasticsearchExtension] class is available in the case where there is no error.

Does anyone have an idea of what the root cause could be? I cannot find any discussion about this. So, it is likely that the issue rests with my usage of the client.

Exception stack trace from the logs:
java.lang.IllegalArgumentException: cannot write time value xcontent for unknown value of type class java.util.Date
at org.elasticsearch.common.xcontent.XContentBuilder.timeValue(XContentBuilder.java:751)
at org.elasticsearch.common.xcontent.XContentBuilder.unknownValue(XContentBuilder.java:815)
at org.elasticsearch.common.xcontent.XContentBuilder.value(XContentBuilder.java:804)
at org.elasticsearch.common.xcontent.XContentBuilder.field(XContentBuilder.java:789)
at org.elasticsearch.index.query.RangeQueryBuilder.doXContent(RangeQueryBuilder.java:322)
at org.elasticsearch.index.query.AbstractQueryBuilder.toXContent(AbstractQueryBuilder.java:87)
at org.elasticsearch.index.query.BoolQueryBuilder.doXArrayContent(BoolQueryBuilder.java:274)
at org.elasticsearch.index.query.BoolQueryBuilder.doXContent(BoolQueryBuilder.java:255)
at org.elasticsearch.index.query.AbstractQueryBuilder.toXContent(AbstractQueryBuilder.java:87)
at org.elasticsearch.common.xcontent.XContentBuilder.value(XContentBuilder.java:857)
at org.elasticsearch.common.xcontent.XContentBuilder.value(XContentBuilder.java:850)
at org.elasticsearch.common.xcontent.XContentBuilder.field(XContentBuilder.java:842)
at org.elasticsearch.search.builder.SearchSourceBuilder.innerToXContent(SearchSourceBuilder.java:1224)
at org.elasticsearch.search.builder.SearchSourceBuilder.toXContent(SearchSourceBuilder.java:1355)
at org.elasticsearch.common.xcontent.XContentHelper.toXContent(XContentHelper.java:367)
at org.elasticsearch.client.RequestConverters.createEntity(RequestConverters.java:768)
at org.elasticsearch.client.RequestConverters.createEntity(RequestConverters.java:763)
at org.elasticsearch.client.RequestConverters.search(RequestConverters.java:417)
at org.elasticsearch.client.RestHighLevelClient.lambda$search$2(RestHighLevelClient.java:1071)
at org.elasticsearch.client.RestHighLevelClient.internalPerformRequest(RestHighLevelClient.java:1609)
at org.elasticsearch.client.RestHighLevelClient.performRequest(RestHighLevelClient.java:1583)
at org.elasticsearch.client.RestHighLevelClient.performRequestAndParseEntity(RestHighLevelClient.java:1553)
at org.elasticsearch.client.RestHighLevelClient.search(RestHighLevelClient.java:1069

2

The date transformer for java.util.Date is provided by org.elasticsearch.common.xcontent.XContentElasticsearchExtension which is dynamically loaded from elasticsearch-7.9.2.jar. I suspect this could happen if your current classloader doesn't know about this jar yet, perhaps because you have not yet loaded any other class from it. Try calling org.elasticsearch.common.xcontent.XContentElasticsearchExtension#getDateTransformers() yourself first to ensure that this class is loaded.

If that fixes your problem then please report this as a bug.

3

David, I have added code you have suggested above and am waiting for the issue to reoccur. As I mentioned, this is sporadic and only occurs rarely (~once a week).

This was my code before I added your suggestion

try {
            return client.search(request, RequestOptions.DEFAULT);
        } catch (IllegalArgumentException e) {
                logger.error("Error while searching elastic search: 1", e);
                int numXcontentbuilderextension = 0 ;
                for (XContentBuilderExtension service : ServiceLoader.load(XContentBuilderExtension.class)) {
                    logger.info("XContentBuilder: " + service.getClass().toString());
                    var dateTransformers = service.getDateTransformers();
                    logger.info("XContentBuilder [num DateTransformers]:" + dateTransformers.size() + " isNull: " + dateTransformers.containsKey(Date.class));
                    numXcontentbuilderextension ++;
                }
                logger.info("Number of XContentBuilderExtensions: " + numXcontentbuilderextension);
}

When the exception happens, the following gets printed.

Error while searching Elasticsearch: 1
INFO XContentBuilder: class org.elasticsearch.common.xcontent.XContentElasticsearchExtension
INFO XContentBuilder [num DateTransformers]:16 true
INFO Number of XContentBuilderExtensions: 1

When this happens, this issue is localized to a particular replica. Which suggests that the issue rests with the client. Are there any known reasons for why the ServiceLoader.load fails once and then succeeds on the second call. Another interesting observation is that , there are more failures for the same code path on the same thread few more seconds down the line.

PS: We are using SpringBoot 2.3.1.RELEASE, Spring v5.2.7.RELEASE

4

Yes, as I said:

5

Yes, but, if the issue reoccurs in the same thread, after
"INFO XContentBuilder: class org.elasticsearch.common.xcontent.XContentElasticsearchExtension" which indicates that the class has been loaded, your hypothesis has already been tested, right?

6

Not exactly, it looks like it may depend on the classloader being used, and this is not fixed even on a single thread. I'm not familiar with how Springboot works under the hood but it definitely does mess around with the context classloader which could lead to this.

However, you are correct that this is very much a hypothesis (i.e. a guess) to be tested rather than a definite answer.

7

Got it. Thanks David. I'll report back once the issue occurs and report back on the results of the test.

1 Like
8

Hi David,
The issue resurfaced now after 4 days. Here
This is how the ES invocation looks

>  try {
            return client.search(request, RequestOptions.DEFAULT);
        } catch (IllegalArgumentException e) {
            logger.error("Error while searching elastic search: 1", e);
            int numXcontentbuilderextension = 0 ;
            for (XContentBuilderExtension service : ServiceLoader.load(XContentBuilderExtension.class)) {
                logger.info("XContentBuilder: " + service.getClass().toString());
                var dateTransformers = service.getDateTransformers();
                logger.info("XContentBuilder [num DateTransformers]:" + dateTransformers.size() + " isNull: " + (dateTransformers.get(Date.class) == null));
                numXcontentbuilderextension ++;
            }
            logger.info("Number of XContentBuilderExtensions: " + numXcontentbuilderextension);
            logger.info("XContentElasticsearchExtension [num DateTransformers]: " + new org.elasticsearch.common.xcontent.XContentElasticsearchExtension().getDateTransformers().size());
            try {
                return client.search(request, RequestOptions.DEFAULT);
            } catch (Exception exception) {
                logger.error("Error while searching elastic search: 3", exception);
                return null;
            }
        }

The following output is produced when the exception occurs,

Error while searching elastic search: 1
XContentBuilder: class org.elasticsearch.common.xcontent.XContentElasticsearchExtension
XContentBuilder [num DateTransformers]:16 isNull: false
Number of XContentBuilderExtensions: 1
XContentElasticsearchExtension [num DateTransformers]: 16
Error while searching elastic search: 3

From the above, it looks like the jar is loaded, but nevertheless results in an exception ,
"java.lang.IllegalArgumentException: cannot write time value xcontent for unknown value of type class java.util.Date".

I am now completely baffled by this. Do you have any leads/guesses (varying levels of crazy are accepted at this point) on what could cause this?

9

I too am baffled then. I would suggest reporting this as a bug, along with all the investigation you've done so far.

10

Got it. Thank you for your help. Do you know the best place to report the bug. Github?

11

Yes, here please --> https://github.com/elastic/elasticsearch/issues/new/choose

12

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.