Enhance exception serialization ?

[Thomas Bolon]

Hi,

Some background first : we are trying to use serilog/seq to replace our existing event logging mechanism and at this time it seems to be extremely promising. We have actually 2 reporting channels : one for unhandled exceptions, another for event logging. So it's different from serilog which allows for logging, by eventually attaching an exception.

I want to try to replace our both systems by serilog, but I am facing a limitation regarding the way exceptions are sent to seq.

Currently, only the exception name and the stacktrace are sent (using ToString()) in SeqJsonFormatter. Compared to our previous system, it's lacking a lot of data : we used to report most exception properties (including Data Hashtable which often include more diagnostics informations) and inner exceptions. We also detected AggregateException to better deserialize InnerExceptions properties.

Do you agree with the suggestion that SeqJsonFormatter could be enhanced to provide better details in the Json sent to seq ?

How seq will handle the Exception json property if, instead of raw text, a full object is sent ?

I am planning to fork seq-client to make some tests in my computer, using seq raw json to check how exception are stored, but I wanted your advice first.

Regards,

[nblum...@nblumhardt.com]

Hi Thomas!

We discussed this on a Serilog ticket a while ago (https://github.com/serilog/serilog/issues/78) - the solution we came to was to create something like this: https://gist.github.com/nblumhardt/dddaa2139bbf4b561fa7

This results in exceptions being logged with this kind of structure:

{
  "Timestamp": "2014-06-26T07:51:23.7104866+10:00",
  "Level": "Error",
  "MessageTemplate": "Here's an error",
  "Exception": "System.InvalidOperationException: This is an error\r\n   at ...<snip>",
  "Properties": {
    "ExceptionData": {
      "ExtraInfo": 123
    }
  }
}

In Seq, queries like ExceptionData.ExtraInfo > 10 can be written against this.

I initially understood this to be a fairly unusual requirement, but it turns out not to be so :) If you have a chance to look at and try the enrichment approach (we may be able to extend it or create additional enrichers of this kind) then it's something we could support in Serilog core.

(Perhaps destructuring the exception into a single "DetailedException" property, complete with "Message", "InnerException" and so-on would be nice? AggregateException and friends do make this somewhat tricky to work with though.)

Would love to hear your thoughts, thanks for posting!

Nick

[k...@kristofferjansson.com]

I've been wanting this as well. Another example is ReflectionTypeLoadException which carry all the interesting bits in the LoaderException property.

However, using a custom enricher may solve most of these problems for now. A standard way would be preferable, since you'd have to know how different enrichers log exceptions to be able to query them properly.

/Kristoffer

[nblum...@nblumhardt.com]

Interesting additional example. The whole "wrapping" thing that is so prevalent in .NET exceptions makes this a challenging feature, but one that could be really cool...

The additional data doesn't seem so much a case of serializing the entire exception (with inner exceptions, loader exceptions, etc.) but more like pattern matching to find interesting/useful properties within that hierarchy, and ideally flattening that out in a way that can be queried naturally. No idea how this would look; if my exceptions carry an "ExtraInfo" property in Data though this is the kind of thing I mean:

.Enrich.With(new ExceptionDataEnricher(enrich => {
  enrich.On(e => e.Data.Contains("ExtraInfo"), e => new { ExtraInfo = e.Data["ExtraInfo"] });
  enrich.On<MyAppException>(e => new { AppInfo = e.AppInfo });
});

The set of rules would identify matching exceptions of a type or using a predicate, then create properties containing the relevant data. That way, wrappers like ReflectionTypeLoadException, AggregateException and so-on don't make querying miserably hard - they're unwrapped by the enricher automatically.

The second example might support a Seq query like ExceptionData.AppInfo == "Hello!".

I like this in preference to the alternative, which is to provide some kind of XPath/CSS-like language for selecting exceptions... Match(@Exception, **.MyAppException[AppInfo] == "Hello!) etc. Too complex to design, document, use and maintain for the limited use cases it would support.

How's this sound? Should we open a Serilog ticket for it? Better ideas? :)

[k...@kristofferjansson.com]

Interesting. Are you suggesting that ExceptionDataEnricher would traverse the exception's InnerException as well, applying the rules to any inner exceptions also?

Would ExceptionDataEnricher come with any pre-defined rules for common .NET exceptions?

[nblum...@nblumhardt.com]

"Yes", and "yes", I think. Still some challenges to keep it simple (bailing if, say, an exception type appears more than once in the aggregate) but seems possible :)

[k...@kristofferjansson.com]

Ok, then I like this idea :-)

[Thomas Bolon]

Sorry for the delay, I did not receive notifications for new replies.

I'll read all answers posted here then reply later.

Thanks !

[Thomas Bolon]

For now I have implemented something similar, when an ExceptionEnricher takes a collection of IExceptionDestructurer in ctor.

public interface IExceptionDestructurer

{

    Type TargetType { get; }

    void Destructure(Exception exception, IDictionary<string, object> data, Func<Exception, IDictionary<string, object>> innerDestructure);

}

Then I see two ways of using this :

1. You can destructure exception in the most complete way, using reflection over properties and object to object conversion.

Each property value is inspected for patterns such as IDictionary or IEnumerable or TypeCode to either return the same value, or an IDictionary or an IList where you destructure elements recursively.

It's implemented by calling ExceptionEnricher with a unique ReflectionBasedExceptionDestructurer.

2. You can destructure exceptions the most conservative way, by passing some IExceptionDestructurers which only match specific types.

Some core destructurers could be provided to match cases :

• ExceptionDestructurer for the Exception type, which recursively call innerDestructure with InnerException if present.
  
• AggregateExceptionDestructurer which handles the InnerExceptions property.
• ReflectionTypeLoadExceptionDestructurer which handles the LoaderExceptions property.

And others could be easily added to include details (SqlException comes into my mind immediately).

The main difference between the two methods is obviously performances. The first method is the quick-and-dirty way, with the reflection toll, but produces the best results at start.

The second one involves only casting and will certainly performs better, but at the cost of explicit exception handling.

I have implemented all of these in a custom library. For now I am still trying to determine the cost of the reflection examination compared to the cost of raising the exception itself.

[Konstantin Erman]

Thomas,

Could you please share your implementation? What you listed above looks very promising and I hope to learn from your code.

Thank you!

Konstantin

[Thomas B]

Here it is : https://gist.github.com/tbolon/81dca3e2777d42c0108e

Please note that it's some files merged together in one gist. There are perhaps some typos errors (missing using).

Also we are only using ExceptionEnricher.ReflectionBased for now, because reflection did not seems to be really costly for now (we only log a few exception this way).

Glad it could help you.

Regards

[Konstantin Erman]

Thomas, thank you very much for the speedy answer! The code is very interesting and definitely saved me tons of research type. Here are a few notes:

1.  this.destructurers = destructurers ?? DefaultDestructurers; This code does not work as expected. When public constructor for ExceptionEnricher is invoked with no parameters, "destructurers" parameter is not null, but rather empty array, therefore ?? operator causes "destructurers" field to be empty collection (rather than fallback to DefaultDestructurers collection) and as the result ExceptionEnricher does not work at all.

2. data.Add("$Type", exception.GetType().FullName); Here I believe dollar sign supposed to mean stringification (in Serilog sense), but for whatever reason it does not work here and Type property does not get emitted at all. Frankly I don't quite understand why we need stringification here as FullName is the string anyway, so I just removed that dollar sign in my version.

3. Regarding ReflectionBasedDestructurer - I don't understand how it is better than collection of specialized exception destructurers. Could you please explain what problem it solves for you?

4. I noticed that Seq still outputs default exception stack (in the dark red). Wonder how to suppress it, as I'm going to provide better stack through my specialized destructurer.

5. Currently exceptions should be reported through methods like Log.Error(ex, "MessageTemplate"). In many cases people want to just log the exception like Log.Error(ex). In this case event message become empty. I wonder how to create some syntetic (automatic) message for the case when message is not supplied from the data available in exception object. This is more like "food for thought". For the beginning simple ex.Message would do. 

Thank you!

Konstantin

[Thomas B]

1. You are right, it's a bug. My fault because I've only used reflectionbased

2. the $ Sign was only a "marker" to ensure that an exception with a property named Type could not be overwritten by this property (which is metadata). You could replace the $ by any invalid property name smybol.

3. Without reflection based, you only track specific object properties for the exceptions implemented. If you have an exception type which implement a specific property (ex: resultcode) by default it's not serialized. You need to implement a destructurer for all exceptions you want to track (or you will have only base Exception properties). ReflectionBasedDestructurer ensure you that always all exceptions are serialized, but it's more costly, and could leverage bugs (when scanning the object graph).

4. I don't know, it's not really a problem for us, the most important is to have a detailed exception, so we could better analyze exceptions.

5. Why not set the LogEvent.Message property if empty, using the Exception.Message ? I am speaking without watching code.

[Konstantin Erman]

Thomas,

I'm looking at your reflection based exception destructurer and cannot comprehend one fragment in DestructureValue method:

            if (valueType.IsSubclassOf(typeof(MemberInfo)))
            {
                return value;
            }
 
            if (Type.GetTypeCode(valueType) != TypeCode.Object || valueType.IsValueType)
            {
                return value;
            }

As far as I understand the first if statement supposed to handle Exception.TargetSite property (which is of type MethodBase). Why do you check against typeof(MemberInfo) in this case?

Second if statement (Type.GetTypeCode(valueType) != TypeCode.Object) is also not clear to me. What exactly it is trying to achieve?

Thank you!

Konstantin

[Thomas B]

First, the fact to return value will result in the method value.ToString() to be used. So, it's the way to go when we think that the property value does not need to be traversed and can be displayed directly.

1) MemberInfo is the base class for all types used in reflection. They expose a lot of properties and a complex object graph (often with recursive loop). So this shortcut prevent any unnecessary work.

2) TypeCode is a quick way to check if a type is a standard value type. For all cases different from object, a simple object.ToString() will be sufficient, you can browse the enum to see all types concerned. IsValueType is also a shortcut for all types which are struct, and for which I suppose a ToString() will be ok (think Point, Rectangle, DateTime, Guid, etc.).

The idea here is to cover most custom exception types, not only Exception base type, and prevent some edge cases. In our application, we have a lot of custom exception, which sometimes add new properties with complexe objects.

[Konstantin Erman]

Thank you, Tomas! I got it now. Compliments with a pretty sophisticated code - very short and covers very broad range of cases.