Same Key Added Exception in ExceptionPropertiesBag

[jtillyt]

Describe the bug

While using in the field within a heavily multi-threaded application, it was found that we there are cases in which a handled exception in user code was being passed to Serilog where the reflection part of this enricher was throwing the error below. I'd be more than happy to help with a fix if needed but wanted to create the bug report before creating a PR in case this was a known issue with a fix in place.

It appears that the ExceptionPropertiesBag could be made thread safe by using either locks when accessing the Dictionary or by using a ConcurrentDictionary without affecting too much of the existing code.

[0:] 2022-02-10T21:55:43.7341420Z Exception System.ArgumentException: An item with the same key has already been added. Key: Error
  at System.Collections.Generic.Dictionary`2[TKey,TValue].TryInsert (TKey key, TValue value, System.Collections.Generic.InsertionBehavior behavior) [0x0015a] in <dfdfd170633c4311845cda2ff4af9f6b>:0 
  at System.Collections.Generic.Dictionary`2[TKey,TValue].Add (TKey key, TValue value) [0x00000] in <dfdfd170633c4311845cda2ff4af9f6b>:0 
  at Serilog.Exceptions.Core.ExceptionPropertiesBag.AddProperty (System.String key, System.Object value) [0x0004a] in D:\a\Serilog.Exceptions\Serilog.Exceptions\Source\Serilog.Exceptions\Core\ExceptionPropertiesBag.cs:59 
  at Serilog.Exceptions.Destructurers.ReflectionBasedDestructurer.AppendProperties (System.Object value, Serilog.Exceptions.Destructurers.ReflectionBasedDestructurer+ReflectionPropertyInfo[] reflectionPropertyInfos, System.Action`2[T1,T2] addPropertyAction, System.Collections.Generic.IDictionary`2[TKey,TValue] destructuredObjects, System.Int32 level, System.Int32& nextCyclicRefId) [0x00082] in D:\a\Serilog.Exceptions\Serilog.Exceptions\Source\Serilog.Exceptions\Destructurers\ReflectionBasedDestructurer.cs:187 
  at Serilog.Exceptions.Destructurers.ReflectionBasedDestructurer.Destructure (System.Exception exception, Serilog.Exceptions.Core.IExceptionPropertiesBag propertiesBag, System.Func`2[T,TResult] destructureException) [0x0006a] in D:\a\Serilog.Exceptions\Serilog.Exceptions\Source\Serilog.Exceptions\Destructurers\ReflectionBasedDestructurer.cs:87 
  at Serilog.Exceptions.Core.ExceptionEnricher.DestructureException (System.Exception exception) [0x0006c] in D:\a\Serilog.Exceptions\Serilog.Exceptions\Source\Serilog.Exceptions\Core\ExceptionEnricher.cs:94 
  at Serilog.Exceptions.Core.ExceptionEnricher.Enrich (Serilog.Events.LogEvent logEvent, Serilog.Core.ILogEventPropertyFactory propertyFactory) [0x00024] in D:\a\Serilog.Exceptions\Serilog.Exceptions\Source\Serilog.Exceptions\Core\ExceptionEnricher.cs:65 
  at Serilog.Core.Enrichers.SafeAggregateEnricher.Enrich (Serilog.Events.LogEvent logEvent, Serilog.Core.ILogEventPropertyFactory propertyFactory) [0x0000f] in <21bca8243af74b5ba3d897d8e6c79e81>:0  caught while enriching Serilog.Events.LogEvent with Serilog.Exceptions.Core.ExceptionEnricher.
Thread finished:  #554

Version:

Using Version 8.0.0 with additional duplicate key handling:
3445242

Platform:
Xamarin Forms, primarily targeting iOS

Steps to reproduce

This is hard to reproduce as it needs the same or similar exceptions being thrown in multiple environments. This tends to happen in code that does many retries such as HTTP retries or other error prone / retry heavy code in which the exceptions are being caught and logged.

Expected behaviour

When this exception occurs, the app does a hard crash and does not always push the error out to file logs though the logs can be retrieved from the Console while debugging.

[krajek]

From a quick look, it may be the case that we actually handle duplicate names incorrectly in this scenario.
Thanks for the report I will try to take a look at this in terms of code in the evening.
I don't think it has anything to do with the thread-safety, within one ExceptionPropertiesBag there is no concurrency.

[krajek]

@jaytilly on the second look, I change my mind, I don't know how to reproduce this one. Why do you think this involves some threading issue?

[jtillyt]

@krajek, I don't (yet) have exact repro steps that can be followed or a code-base that I can share freely but I arrived at the possibility of threading due to the places in code that the error tends to occur around. It seems to be in areas where there is a lot of concurrency with the same exception(s) being thrown on different threads. I'll dig in to try and narrow down the cause a bit later in the day.

I appreciate the quick reply.

[RehanSaeed]

The ConcurrentDictionary would be the best approach if this is indeed a concurrency issue (I've not looked deeply).

[RehanSaeed]

Anyone had a chance to look at resolving this?