UnexpectedElasticsearchClientException while logging

[xumix]

Basically a copy from elastic/elasticsearch-net#5702
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

Is there any way to get some details of what is being posted?
What is the proper way to replace default serializer with nest.jsonnetserializer?

[snakefoot]

Please provide the NLog.config configuration you are using for setting up the NLog ElasticSearch Target.

Yes the JsonSerializer provided with ElasticSearch.Net LowLevel client is very fragile, and can only handle the most simple objects. Many applications has been killed by stackoverflow because object-recursion is not handled.

NLog.Targets.ElasticSearch includes automatic protection against the dangerous Exception-objects, as they can include exotic object-references in their Exception.Data-collections.

But as structured logging has become more common, then people are also logging exotic object-references, which causes the ElasticSearch.Net LowLevel client to explode in your face.

You can try and configure MaxRecursionLimit=1, and see if it gives the expected output without generating errors. See also: https://github.com/markmcdowell/NLog.Targets.ElasticSearch/wiki

[stevejgordon]

@snakefoot I've added a hopefully more helpful exception with more descriptive message inside the anonymous type serialization code path in this PR. This should make it into the 7.13 release as long as CI is happy with it. Feel free to suggest anything further which would be useful for your library to leverage.

I agree the serializer has some issues and for the next major my goal is to replace this to use System.Text.Json throughout. As a general rule, indexing deeply nested types is not recommended and querying them can be more expensive, but I appreciate why this happens in structured logging scenarios.

[xumix]

Please provide the NLog.config configuration you are using for setting up the NLog ElasticSearch Target.

<target name="elastic" xsi:type="BufferingWrapper" flushTimeout="5000">
      <target xsi:type="ElasticSearch"
              name="elastic"
              uri="${appsettings:name=ConnectionStrings.ElasticLogUrl}"
              index="nlog-${date:format=yyyy.MM.dd}"
              documentType="logevent"
              includeAllProperties="True"
              excludedProperties="EventId_Id,EventId_Name"
              disableAutomaticProxyDetection="True"
              requireAuth="False"
      >
        <field name="machineName" layout="${machinename}" />
        <field name="siteName" layout="${iis-site-name}" />
        <field name="level" layout="${level}" />
        <field name="username" layout="${aspnet-user-identity}" />
        <field name="message" layout="${message}" />
        <field name="logger" layout="${logger}" />
        <field name="callsite" layout="${callsite:includeSourcePath=true}" />
        <field name="serverName" layout="${aspnet-request:serverVariable=SERVER_NAME}" />
        <field name="port" layout="${aspnet-request:serverVariable=SERVER_PORT}" />
        <field name="url" layout="${aspnet-request-url}?${aspnet-request-querystring}" />
        <field name="method" layout="${aspnet-request-method}" />
        <field name="userAgent" layout="${aspnet-request-useragent}" />
        <field name="serverAddress" layout="${aspnet-request:serverVariable=LOCAL_ADDR}" />
        <field name="remoteAddress"
               layout="${aspnet-request:serverVariable=REMOTE_ADDR}:${aspnet-request:serverVariable=REMOTE_PORT}" />
        <field name="exception" layout="${exception:format=ToString}" />
        <field name="mdlc" layoutType="System.Object">
          <layout xsi:type="JsonLayout" includeMdlc="true" />
        </field>
      </target>
    </target>

You can try and configure MaxRecursionLimit=1, and see if it gives the expected output without generating errors. See also: https://github.com/markmcdowell/NLog.Targets.ElasticSearch/wiki

I'll try it, but suppose that wont help, my app does not crash but just eats a lot of RAM and I can't figure what particular log is causing this.

@snakefoot Do you recommend using ECS layout for mitigating serialization problems? Or how do I use Newtonsoft serializer instead?
I also have file target but can't find any messages that can be problematic with Elastic target

[snakefoot]

I have very little experience with ElasticSearch. But EcsLayout has a bug, where it fails to handle certain exception-objects. Make sure to use Elastic.CommonSchema.NLog ver. 1.5.3 (or newer).

I would probably change from BufferingWrapper (that flushes every 5000 ms) into AsyncWrapper (that flushes every 200 ms):

<target name="elastic" xsi:type="AsyncWrapper" timeToSleepBetweenBatches="200">
    <target xsi:type="ElasticSearch" name="elastic" maxRecursionLimit="1" />
</target>

[xumix]

Thanks! I'll try that!

[xumix]

Still no luck, I've replaced the serializer like this, will see if that helps

var defaultConstructor = ConfigurationItemFactory.Default.CreateInstance;
ConfigurationItemFactory.Default.CreateInstance = type =>
            {
                if (type == typeof(ElasticSearchTarget))
                {
                    var target = (ElasticSearchTarget)defaultConstructor(type);
                    target.ElasticsearchSerializer = new ElasticNewtonsoftSerializer();
                    return target;
                }

                return defaultConstructor(type);
            };

LogManager.Configuration.Reload();

[snakefoot]

When "not working" could you give some details of what fails? Maybe include output from the Nlog InternalLogger. Maybe things can be improved to help future users.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.