Allow logged objects to be exploded into multiple parameters.

[jonwagner]

Sounds promising.

Rather than "rolling up" parameters into serialized/discrete parameters, my use case is more oriented to "un-rolling" or "promoting" object values into discrete schema values. I was envisaging a serialization provider that, in place of (or addition to) returning a string, returned a Dictionary representing Schema keys and payload values.

Alternatively, how about an "inspecting" serializer to which you pass a bunch of Expression instances which inspect and return a value. The expression can be examined to evaluate a schema name and return type and compiled to quickly retrieve payload values at runtime.

For example, with an EmailChanged signature as follows:

void EmailChanged(IEmail email)

I would like to register something like:

EventSourceImplementer.RegisterProvider(new InspectingObjectSerializer( new Expression [] { source => source.UserId, source => source.Old, source => source.New } ));

And would expect to see three discrete values (prefixed by the container objects parameter name to differential multiple parameters of the same type) in the logged event; email.UserId, email.Old, email.New.

What do you think? I'd be happy to invest some time helping implement the InspectingObjectSerializer.

Cheers, Ian

[jonwagner]

In implementing an EventSource from an interface, there are two steps:

1. Interface Method -> Call EventSource Method
2. EventSource Method -> Call WriteEvent.

Let's work our way backward:

• WriteEvent has to have the parameters exactly as you want them logged, and by the time you call it, all parameters need to be serialized.
• The EventSource Method has to have the same signature as the call to WriteEvent.
• That leaves us the interface implementation to do the magic.
• Our goal is to have the interface implementation be "as natural to the code" as possible, and when implementing a proxy around an existing interface, it has to match.

The code I'm working on for TraceParameterProvider, allows the provider to inspect the interface method and return a list of the parameters that it wants logged. Basically, the ParameterMapping list it returns becomes the definition of the EventSource/CallWriteEvent code.

Currently, each ParameterMapping is allowed to have a list of "sources", which are defined from the Parameters of the interface. I think it will be possible to also allow a source to be additional code that pulls values out of an object.

[jonwagner]

I just checked in a proof-of-concept where you can use expressions to define converters on parameters. So it looks like this is going to work. Next step is to make it "pretty" to define parameter explosions.

[jonwagner]

The default TraceParameterProvider now looks for attributes on methods. Example:

    public interface ILogEmailChangesWithAttributes
    {
        void LogChange(
            [TraceMember("From")]
            [TraceMember("To")]
            [TraceMember("When")]
            EmailChange email,
            [TraceIgnore] string ignored);
    }

That, along with the TraceAs attribute, lets you explode or collapse any set of parameters almost into any form that you would want to log.

If you're building a logging interface, then I think it's fine that the attributes go on the interface. However, if you're proxying a functional interface, it's probably not the place you should put this mapping. So we need a provider for it.

[jonwagner]

The provider model lets you inspect the signature of a method (just a MethodInfo), and build up the signature of the logging function. It is:

List of ParameterMapping
     ParameterMapping defines the name of the logged parameter
     List of Sources defines where to get the data to log
            Source is a parameter from the method call, plus an optional Expression to convert the data
            If there is one source, then the value is logged directly.
            If there are multiple sources, then the values are logged as a string/string dictionary

So the infrastructure is there. We just need a provider with a nice fluent configurable interface. (Or possibly an XML-based interface).

I think I'd like to be able to do things like this:

For<ILogEmail>().With<EmailAddress>().Log(e => e.From).Log(e => e.To)
Always().With<EmailAddress>().Log(e => e.Domain)
For<ILogEmail>().Method("LogChange").With<EmailAddress>().Log(e => e.When)
For<ILogEmail>().Method("LogChange").Log("From", "To", "When")
For<ILogEmail>().Method("LogChange").LogAll().Except("When")

Basically a bunch of filters: * Interface * Method * Apply always to a type * Log specific parameters * Log expressions based on specific parameters * Include all except

I think a fluent interface could map pretty easily to data structures that a parameter provider could use to generate the list of parameter mappings.

Ian - you might be the best person to comment on how you would want to configure it.

[ibebbs]

Hi Jon,

I've looked through your changes and like the direction this is headed. I've just issued a pull request from a fork of the project in which I've implemented a "EventDataProvider" which shows a simple way of using LambdaExpressions to define the logging requirements without needed any reflection.

That said, having read your ideas about being able to configure instrumentation at multiple levels via a fluent and/or XML configuration, I wonder whether this simplification would be as flexible. Anyway, it's there if you'd care to take a look.

We currently use Ninject's fluent syntax for configuration of our DI container, ergo I am very interested in the fluent API suggested above and would be happy with the static/compile time configuration it implies. I imagine being able to configure the instrumentation from XML config file would be beneficial to some but is probably less useful - and more work - than the fluent API right now. What do you think?

[ibebbs]

Couple of additional use cases for the fluent API (very much nice to haves):

Naming of schema value: For().Method("LogChange").With().Log(e => e.When).As("SentAt")

Using methods to generate output: For().Method("LogChange").With().Log(e => e.When.ToUniversalTime())

[ibebbs]

It occurs to me that lots of mocking/faking frameworks employ similar fluent API's. Might be worth looking at how something like FakeItEasy interrogates Lambda expressions in order to use a identify a specific method to mock (or, in our case, trace) instead of finding the method via a name (which won't be as flexible when it comes to overloading nor as maintainable when refactoring).

Just a thought.

Would you like a hand with any of the above?

[jonwagner]

I agree. I like the code you did for the EventDataProvider, but I think we can have more flexibility. I've use Ninject and Moq, and I like the way they configure things.

I have some ideas on how to get that started (more likely tomorrow than today). Let me put down some baseline code, and you can help me develop the fluent interface.

[ibebbs]

Hi John,

I have just committed (to my fork of EventSourceProxy) a first draft of a fluent API for trace configuration along the lines of the examples you provided above. It's incomplete but several unit tests have been implemented to prove out the approach and show it can collate the required information.

I'd be very interested to know your thoughts on my approaches so far.

Cheers, Ian

[ibebbs]

Actually just managed to find some time to tidy it up and finish off the testing of the first draft.

Hopefully it's along the lines of what you had in mind.

[jonwagner]

I like the direction. I think I can get rid of the value serializer. When the proxy is generated, the accessor expression is actually compiled directly into the proxy.

I'll pull in the changes and wire it up to the proxy this morning. Then we'll see how it all falls out.

[jonwagner]

Ian - your code saved me a lot of time. It may look all deleted, but it was a combination of refactoring/renaming things.

I simplified the syntax.

Method matching: * ForAnything() - match any method * For() - match any method on T * For(expression) - match specific method on T

Trace stuff: * Trace(parameterName) - traces a parameter by name * Trace(parameterName, converter) - traces a parameter by name and applies the conversion lambda * Trace(converter) - traces any parameter matching the type and applies the conversion lambda

Renaming things: * As(alias) - renames the previous thing traced

Bundling stuff together: * And - overloads work like Trace, but combines the value with the previous value(s) * TogetherAs(alias) - aliases things joined by And

Convenience: * With() and EndWith() - scopes a bunch of Trace methods to type T so you don't have to retype the type.

Big example:

        tpp.For<IEmailer>(m => m.Send(Any<IEmail>.Value, Any<DateTime>.Value))
            .With<IEmail>()
                .Trace(e => e.From).As("sender")
                .Trace(e => e.To).As("recipient")
                .Trace(e => e.Subject).As("s")
                    .And(e => e.Body).As("b")
                    .TogetherAs("message")
                .Trace(e => String.Join("/", e.Attachments.Select(Convert.ToBase64String).ToArray()))
                    .As("attachments")
            .EndWith()
            .Trace("when");

This would trace: * sender = e.From * recipient = e.To * message = { s : subject, b : body } * attachments = e.Attachments munged up

For expressions like e=>e.From, if you don't specify an alias, we try to make one up from the method accessor if the expression is simple enough.

Things I'd like to add (in case you're feeling codey):

* TraceAll - so you can trace everything that is unspecified - requires some thought to handle duplicates
* Ignore - partly to remove things from TraceAll, but also possibly so you can set a default rule for a type like Email, then selectively ignore it.
* With + filter by name - so you can scope an object explosion to a specific named parameter
* Alternate syntax for Trace(a).And(b) => Trace("a", "b", ...) or Trace<T>(expr1, expr2...exprn)

Test cases I didn't get to:

* Trace (parameternamefilter + expression) - testing filtering on both

Known issues:

* Since the converters return object (not string), the proxy code attempts to serialize the string, causing it to add quotes.

[jonwagner]

Updated with:

* With<T>(parameterName).Trace(expression) - to filter a set of expressions by parameterName
* Trace<T>(parameterName, expression) - same as the With<T>(parameterName) but only one
* Trace, And, As all can take lists, like:

ForAnything().With<IEmail>().Trace(e => e.From, e => e.To).As("sender", "recipient");

I'm getting happy with this.

Items left:

* TraceAll / Ignore - plus default behaviors so you don't have to specify every parameter
* Eliminate the extra serializer step
* Documentation / code cleanup

[jonwagner]

Whew! All done.

* By default, parameters are traced as is unless a matching rule is added (Trace or Ignore), or an attribute is applied. Rules override attributes.
* The extra serializer step has been removed. Turned out to not be too hard to remove, but it makes With more important.

Take a look. If there are no glaring holes, tomorrow I will write some documentation and merge it into the master branch.

[ibebbs]

Great work Jon! I'll try to put some time aside tomorrow to check it out and provide some feedback.

[jonwagner]

Online wiki documentation has been updated with the latest docs. See Controlling Logged Data.

[jonwagner]

This feature is in v2.0.

v2.0.0-alpha1 is now in nuget. Be sure to select "Include pre-release packages" to get this version.

After some final testing, I'll push out an official 2.0.

[mot256]

I have downloaded your "alpha" release and trying to implement something like this:

public abstract class MyTestEventSource : EventSource
{
    static MyTestEventSource()
    {
        TraceParameterProvider.Default.ForAnything()
            .With<Exception>()
                .Trace(e => e.Message).As("ExceptionMessage")
                .Trace(e => e.StackTrace);
    }

    public static MyTestEventSource Log = EventSourceImplementer.GetEventSourceAs<MyTestEventSource>();

    [Event(1, Level = EventLevel.Error, Message = "Some error: {0}")]
    public abstract void LogError(Exception ex);
}

I'm expecting 2 columns (for the "LogError" event) to be logged to ETW (named "ExceptionMessage" and "StackTrace"), but I'm getting only an "ex" column with the serialisation text of the exception object. Am I missing something here?

[jonwagner]

Hm. At one point I thought that parameter rewriting wouldn't work when deriving from EventSource, and that it only works when logging through an interface.

I know this will work:

public interface IMyTestEventSource
{
    [Event(1, Level = EventLevel.Error, Message = "Some error: {0}")]
    void LogError(Exception ex);
}

// actually, all of this could nicely go into some central logging class
public MyEventSource
{
    static MyTestEventSource()
    {
        TraceParameterProvider.Default.ForAnything()
            .With<Exception>()
                .Trace(e => e.Message).As("ExceptionMessage")
                .Trace(e => e.StackTrace);
    }

    public static MyTestEventSource Log = EventSourceImplementer.GetEventSourceAs<IMyTestEventSource>();
}

But then I also have some test cases where adding attributes to an EventSource class works. This may also work at the moment:

public abstract class MyTestEventSource : EventSource
{
    public static MyTestEventSource Log = EventSourceImplementer.GetEventSourceAs<MyTestEventSource>();

    [Event(1, Level = EventLevel.Error, Message = "Some error: {0}")]
    public abstract void LogError(TraceMember("Message"), TraceMember("StackTrace")] Exception ex);
}

I was expecting people to use attributes on EventSource classes, and rules-based configuration for interfaces, so I don't have full test coverage on all of the permutations. I'll spend some time trying to get your example to work, but try some of the other methods above.

[mot256]

I have tried the TraceMemberAttribute idea, and yes it works, but that requires one to apply the attributes everywhere you pass the object (in this case the Exception object) to the log method so that it will have a consistent output to the log. But with the "rules-based configuration" option one can "configure" the way an object (of a certain class) is logged, at a central place. Another question (regarding performance): I assume that these rules (and/or Attributes) define how the proxy class is generated and that the rules (or attributes) are not evaluated each time the logging method is called?

[jonwagner]

You're right on both counts. I'll try to get the rules to work with EventSource classes. If the attributes work, then I'm just missing something pretty small.

Yes, the rules and attributes are only used to generate the proxy. After that, the methods just look like:

public void Log(Exception e, int foo)
{
    if (IsEnabled())
        WriteEvent(<guid1>(e), <guid2>(e), foo);
}

private static string <guid1> (Exception e) { return e.Message; }
private static string <guid2> (Exception e) { return e.StackTrace; }

Although I may also try to inline the expressions instead of using static methods.

[jonwagner]

I just wrote a test case that has this working. It turns out that your issue is the class initializer is initializing Log before calling the cctor, so the proxy is created prior setting up the rules.

public abstract class MyTestEventSource : EventSource
{
    static MyTestEventSource()
    {
        TraceParameterProvider.Default.ForAnything()
            .With<Exception>()
                .Trace(e => e.Message).As("ExceptionMessage")
                .Trace(e => e.StackTrace);

        // manually create the log after setting up the rules.        
        Log = EventSourceImplementer.GetEventSourceAs<MyTestEventSource>();
    }

    // if you put it here, it would get initialized before the class constructor above
    public static MyTestEventSource Log;

    [Event(1, Level = EventLevel.Error, Message = "Some error: {0}")]
    public abstract void LogError(Exception ex);
}

[mot256]

That makes sense (at least why it did not work). Thanks, will change it as above.