AutoMapper exceptions cause sink to crash process.

[scmccart]

Describe the bug Exceptions thrown by AutoMapper cause the sink to consume all available memory and eventually crash the process. There seems to be a delay until the sink decides to flush the buffered events. The appears to only happen with AutoMapper exceptions.

To Reproduce Steps to reproduce the behavior:

1. Add Azure Analytics Sink to a project and configure it.
2. Add AutoMapper to the project.
3. Add a resolver to your AutoMapper configuration that throws an exception.
4. Use the AutoMapper configuration in order to cause the exception to be thrown and logged.

Expected behavior The application should log the exception in the same manner it logs others.

Additional context We isolated this by assuming that the delayed nature of the crash was a logging sink, we tried combinations until we isolated it to this sink.

[saarivirtajCGI]

Reply from beyond the grave...

Yeah, can confirm. The problem lies in JSON serialization, or precisely in here: https://github.com/saleem-mirza/serilog-sinks-azure-analytics/blob/fd97ca4f43f60eb616f40934faeb7c20acbea282/src/Serilog.Sinks.AzureAnalytics/Sinks/AzureAnalytics/AzureLogAnalyticsSink.cs#L177-L182

This one is also easyish to reproduce, trying to serialize an AutoMapperMappingException produces the exact same behavior.

So the problem itself isn't exactly in the sink, it simply serializes what is given to it with Newtonsoft.Json - but since it just blindly serializes it, and Newtonsoft cannot provide a checking/method to skip circularity, here we are.

Maybe a quick workaround could be a custom JSON Serializer, which can then be injected via reflection to the sink, perhaps. In any case, the JObject.FromObject() is the culprit here and things go haywire when the Exception object gets processed.

[saarivirtajCGI]

Ok, so here's a workaround:

https://gist.github.com/saarivirtajCGI/0131da367b1a7b45fd903992240d72e2

It's not pretty, but it does stop the stack overflow and the resulting app crash, and still logs exceptions. It's a stopgap solution until a better one is implemented.

[saleem-mirza]

thank you very much @saarivirtajCGI and @scmccart for reporting issue. Please share a testable sample project to reproduce this defect.

[SanderDeclerck]

At my company, we had this problem as well. This basically brought our production environment down.

I'll try to create a reproducible example with minimal amount of code in the coming days.

Other sinks we use (File, Debug, ApplicationInsights) seem not to suffer from this. Are they doing things differently?

[saleem-mirza]

@SanderDeclerck, please accept my sincere apology for inconvenience. Please send me minimum viable code to reproduce this defect. Your contribution is highly appreciated.

[lankymart]

@saleem-mirza Is there any movement on this? Not committing to using this sink until this bug is fixed as our project relies heavily on AutoMapper.

[saarivirtajCGI]

@saleem-mirza Is there any movement on this? Not committing to using this sink until this bug is fixed as our project relies heavily on AutoMapper.

@lankymart, having used and stopped using this sink I have to state the obvious problems regarding the way Exceptions are logged by the sink - this is just one problem. All the properties of the Exceptions get flattened and the output can be... staggering. Let's just say that the amount of fields it can gobble up is dangerous. At a glance it doesn't seem like a big problem but when the amount of different Exceptions you get starts to add up, and with different kind of InnerExceptions etc. you can see where this is going:

The worst issue is, it does not matter whether you decide to flatten or not flatten your data: Exception fields still get flattened. The non-flattening behavior is limited to the LogProperties field. So therefore if you log Exceptions your LogAnalytics fields will slowly start to get consumed by Exception fields, and since there's a limit of 500 there's a decent chance you'll hit that hard limit at some point (we did). And when that happens, it can get really messy because of the way the Log Analytics API behaves: if the log batch has one or more rows that would require a new field to be created but the fields are maxed out, it will discard the entire batch. An with Exceptions this is especially bad because the errors are what you're really after but now they don't get logged at all, and all the accompanying log rows are also missing... so good luck finding out what is happening. It's basically a time bomb. You can only get around this by basically not logging Exceptions (which is virtually impossible, and stuff like the Function runtime are out of your control and will log them anyway).

So we did hit the 500 field limit due to this issue and we ended up dropping this sink and Serilog entirely (since it doesn't really bring anything to the table as Log Analytics already offers structural logging) and implementing our own LoggingProvider that similarly uses the Log Analytics API to write logs. We opted for a much more strict approach where we divided log entries by their EventId into several smaller logs (Traces, Exceptions, Requests, Metrics) with preset fields instead of allowing any arbitrary properties to be written. This keeps the logs neat and clean and ensures there will be no ticking time bomb.

As much as this project helped us to get logging fast it also forced us to transition away from it due to these critical issues.

[saleem-mirza]

@saarivirtajCGI @lankymart, appreciated for reaching out. Please mention version of library are you using along with environment information. It will be very helpful if you can please include minimum viable code to preproduce this defect.

Looking forward

[sds-govrn]

@saarivirtajCGI thanks a lot for the workaround, does the job well.