Logging nested distributed function calls with common guid using PostSharp

Question

Currently, each component of a multi-tiered system logs all function invocations using PostSharp.

e.g. an application call to a WCF service might prompt calls to a DataService (in process) and an AuditService (via NServiceBus)

Application -> CaseService: getCaseWithAppointments() (via WCF)
  CaseService -> DataService: getCaseById()
  CaseService -> DataService: getCaseAppointments()
  CaseService -> AuditService: logCaseAccess() (via NServiceBus)

This will result in four rows being written to a log table, but when looking at the log table later, it is not possible to identify that the logCaseAccess() call was called as part of the enclosing getCase() application call.

It would be much more useful if these four rows could be identified as a group.

I can see how it would be possible for the application to generate a Guid which could be passed as a parameter to each subsequent call, but wouldn't this only be possible by changing the signatures for every function across the solution? The solution already includes more than 20 services comprising over 200 OperationContracts, so this would represent considerable effort.

Is there a way of modifying each of the services so that each of their functions knew to expect an additional parameter (the Guid) and to pass that on to any successive calls (perhaps using PostSharp method boundaries)?

I have read this (Is there a way in Log4Net or NLog (or some other logger) to output logs in an execution-stack-nested XML or JSON format?), but unfortunately it did not address the distributed (and multi-threaded) nature of my requirement:

The calls to the WCF services are syncronous, but they call other services via NServiceBus — paul, Mar 19 '15 at 11:16

score 1 · Answer 1 · answered Mar 27 '15 at 14:35

If you have only synchronous code, then the problem of identifying the call stack in the log is often solved by including the current thread ID in the output. This usually can be configured in the underlying logging framework. For example with log4net:

<layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="[%thread] %message%newline" />
</layout>

If you work with async methods, then you would need to use "logical call context". There is a helpful article talking about solving the similar logging issue for async methods: http://blog.stephencleary.com/2013/04/implicit-async-context-asynclocal.html

You can adapt the example in the article to your needs. For example, you can create an OnMethodBoundaryAspect and on method entry save the GUID in the call context if it's not there yet. Since the standard PostSharp logging will not use your custom GUID in the call context, you would need to do the log output in the aspect yourself.

[Serializable]
public class TestAspect : OnMethodBoundaryAspect
{
    private const string Name = "LogId";

    public TestAspect()
    {
        this.ApplyToStateMachine = true;
    }

    public override void OnEntry(MethodExecutionArgs args)
    {
        object contextId = CallContext.LogicalGetData(Name);
        if (contextId == null)
        {
            contextId = Guid.NewGuid().ToString();
            CallContext.LogicalSetData(Name, contextId);
        }

        // Build the log message and send the output to the underlying framework
        Console.WriteLine("{0}: {1}", contextId, args.Method.Name);
    }
}

This was really helpful, and at first looked like it would solve my problem, but unfortunately whether or not the `CallContext` is persisted across subsequent calls appears to be somewhat arbitrary. I don't know if it's relevant, but the services I am trying to log are `InstanceContextMode.Single` and `ConcurrencyMode.Multiple` — paul, Mar 27 '15 at 15:34

Logging nested distributed function calls with common guid using PostSharp

1 Answers1