UnexpectedElasticsearchClientException while logging with Nlog.Targets.ElasticSearch

[xumix]

NEST/Elasticsearch.Net version: 7.10.1

Elasticsearch version: 7.10

We get many exceptions in internal Nlog log with this stacktrace

2021-05-18 19:20:28.3081 Error ElasticSearch: Error while sending log messages Exception: Elasticsearch.Net.UnexpectedElasticsearchClientException: Method may only be called on a Type for which Type.IsGenericParameter is true.
 ---> System.InvalidOperationException: Method may only be called on a Type for which Type.IsGenericParameter is true.
   at System.RuntimeType.get_DeclaringMethod()
   at Serialize(Byte[][] , Object[] , JsonWriter& , RuntimeType , IJsonFormatterResolver )
   at Elasticsearch.Net.Utf8Json.Resolvers.DynamicMethodAnonymousFormatter`1.Serialize(JsonWriter& writer, T value, IJsonFormatterResolver formatterResolver)
   at Elasticsearch.Net.Utf8Json.Formatters.DynamicObjectTypeFallbackFormatter.Serialize(JsonWriter& writer, Object value, IJsonFormatterResolver formatterResolver)
   at Elasticsearch.Net.Utf8Json.Formatters.DictionaryFormatterBase`5.Serialize(JsonWriter& writer, TDictionary value, IJsonFormatterResolver formatterResolver)
   at Elasticsearch.Net.Utf8Json.Formatters.DynamicObjectTypeFallbackFormatter.Serialize(JsonWriter& writer, Object value, IJsonFormatterResolver formatterResolver)
   at Elasticsearch.Net.Utf8Json.JsonSerializer.SerializeUnsafe[T](T value, IJsonFormatterResolver resolver)
   at Elasticsearch.Net.Utf8Json.JsonSerializer.Serialize[T](Stream stream, T value, IJsonFormatterResolver resolver)
   at Elasticsearch.Net.LowLevelRequestResponseSerializer.Serialize[T](T data, Stream writableStream, SerializationFormatting formatting)
   at Elasticsearch.Net.DiagnosticsSerializerProxy.Serialize[T](T data, Stream stream, SerializationFormatting formatting)
   at Elasticsearch.Net.PostData`1.Write(Stream writableStream, IConnectionConfigurationValues settings)
   at Elasticsearch.Net.HttpConnection.SetContent(HttpRequestMessage message, RequestData requestData)
   at Elasticsearch.Net.HttpConnection.Request[TResponse](RequestData requestData)
   at Elasticsearch.Net.RequestPipeline.CallElasticsearch[TResponse](RequestData requestData)
   at Elasticsearch.Net.Transport`1.Request[TResponse](HttpMethod method, String path, PostData data, IRequestParameters requestParameters)
   --- End of inner exception stack trace ---
   at Elasticsearch.Net.Transport`1.Request[TResponse](HttpMethod method, String path, PostData data, IRequestParameters requestParameters)
   at Elasticsearch.Net.ElasticLowLevelClient.DoRequest[TResponse](HttpMethod method, String path, PostData data, IRequestParameters requestParameters)
   at Elasticsearch.Net.ElasticLowLevelClient.Bulk[TResponse](PostData body, BulkRequestParameters requestParameters)
   at NLog.Targets.ElasticSearch.ElasticSearchTarget.SendBatch(ICollection`1 logEvents)

Steps to reproduce:

1. Can't reproduce since this only found on production with high logging volume

Expected behavior
Proper client request processing
More useful message to identify the cause of the problem

[stevejgordon]

Hi @xumix. Thanks for raising this. The original source of this stack is from NLog.Targets.ElasticSearch which is a third-party library built on top of our low-level client. Looking at the code, it may be possible to enable trace/debug NLog internal logging which should then include our DebugInformation. Right now it's only including our basic Exception.

This issue may be related to #2052 where the same error occurred when serialising an Exception. It's possible that you're seeing this occasionally when exceptions have occurred in your code and that is logged via NLog. However, that issue relates to an old version of the client using a different serializer. We now use Utf8Json by default. It looks like the NLog library supports setting an alternative serializer, so you may be able to configure it to use our JsonNetSerializer as an alternative which may resolve the problem.

For support with the NLog package specifically, it may be worth opening an issue with that library. Ideally, if it's possible to identify the payload which is causing the serialization failure, we can investigate it further. Feel free to link back to this one and we can coordinate efforts.

In the mean time, I will try to reproduce this myself and see if there's anything we can do to avoid this exception or handle it differently.

[stevejgordon]

@xumix - I've hacked together a project aimed at reproducing this which replicates the object the NLog library creates and sends as PostData to the Bulk API via the low-level client. With a simple ArgumentException included in the log document it successfully indexes the data. Unfortunately, it's going to be difficult to take this issue forward on our end, without understanding the object(s) being included in the MultiJson which cause the InvalidOperationException to be thrown, so that we can reproduce this. I can certainly review our exception message(s) though.

[xumix]

@stevejgordon Thanks for your efforts! I'll try to raise an issue in the target's repo to get some details

[snakefoot]

@stevejgordon Please consider adding more details to your UnexpectedElasticsearchClientException, so it includes GetType() of the object (T value) that is failing to be serialized.

Then you could better diagnose and re-produce such errors in the future.

[stevejgordon]

@snakefoot Indeed, I will be reviewing this on our end. I should add, this is thrown from a code path which handles serialization of anonymous types so the type info may not be all that useful.

[stevejgordon]

@xumix An improvement should go into 7.13 which may help you identify the type which causes this exception by including it's details in the message. This code path for serialization is specific to anonymous types so I've included property information in the message also. I'll continue digging into the IL generated code to see if I can identify a specific issue there that we need to fix. If you do manage to track down the object causing the serilization failure, please do let me know as we can use that to repro/confirm a fix. In the longer term, we I expect to transition to a more robust serializer (System.Text.Json) in a future major release.

[xumix]

Wow, Thanks for this fast and helpful change!

[snakefoot]

@stevejgordon Thank you very much for adding the extra diagnostic details.

[stevejgordon]

@xumix and @snakefoot - FYI, 7.13.0 just shipped and includes this change.