WCF logging/tracing and activity id propagation using log4net or NLog

Question

I have seen many other questions on logging. Best practices. What logging platform is best. Etc. Here are some links from here on SO with very good discussions on the topic:

logging best practices

log4net vs TraceSource

best logging solution for .NET 3.5 project

.NET 3.5 logging

BEGIN EDIT:

Having typed this long post, I guess that the main thing that I am trying to figure out is how tightly coupled WCF logging/tracing and activity id propagation are to System.Diagnostics and TraceSources. Can you get "good" WCF logging/tracing and activity id propagation using a third party logging platform like log4net or NLog. If you do this, how do you do it?

See the bottom of this post for a few questions about ServiceTraceViewer,

END EDIT.

The subject of my question is not discussed in much detail in any of these posts. I am interested in what people are doing regarding logging and WCF. If you are working on a project that includes WCF services and you have logging in your project, do you make any special efforts to use WCF-specific logging capabilities. In particular, do you try to incorporate things like Activity Tracing, activity propagation, and End to End tracing? Such as is outlined in this article from MSDN. Here is another article from MSDN on propagating activities.

The articles do a pretty job of explaining how to do activity tracing, activity propagation, and end to end tracing using System.Diagnostics TraceSources. It shows how to configure WCF to "turn on" these options via the app.config/web.config file. WCF uses TraceSources internally to log the results of the communication.

Here is some sample code (from the second MSDN article linked above) that shows more or less how to achieve activity propagation via System.Diagnostics and TraceSources:

TraceSource ts = new TraceSource("myUserTraceSource");
Guid oldID = Trace.CorrelationManager.ActivityId;
Guid traceID = Guid.NewGuid();
ts.TraceTransfer(0, "transfer", traceID);
Trace.CorrelationManager.ActivityId = traceID; // Trace is static
ts.TraceEvent(TraceEventType.Start, 0, "Add request");

double value1 = 100.00D;
double value2 = 15.99D;
ts.TraceInformation("Client sends message to Add " + value1 + ", " + value2);
double result = client.Add(value1, value2);
ts.TraceInformation("Client receives Add response '" + result + "'");

ts.TraceTransfer(0, "transfer", oldID);
ts.TraceEvent(TraceEventType.Stop, 0, "Add request");
Trace.CorrelationManager.ActivityId = oldID;

Here is a way that you can tell, from within a service, whether or not WCF has propagated an activity:

// Check if an activity was set in scope by WCF, i.e., if it was 
// propagated from the client. If not, i.e., ambient activity is 
// equal to Guid.Empty, create a new one.
if(Trace.CorrelationManager.ActivityId == Guid.Empty)
{
    Guid newGuid = Guid.NewGuid();
    Trace.CorrelationManager.ActivityId = newGuid;
}
// Emit your Start trace.
ts.TraceEvent(TraceEventType.Start, 0, "Add Activity");

// Emit the processing traces for that request.
serviceTs.TraceInformation("Service receives Add " 
                        + n1 + ", " + n2);
// double result = n1 + n2;
serviceTs.TraceInformation("Service sends Add result" + result);

// Emit the Stop trace and exit the method scope.
ts.TraceEvent(TraceEventType.Stop, 0, "Add Activity");
// return result;

From all of the examples that I have seen, activity propagation is achieved configuring (typically via app.config) the System.Service model TraceSource and setting its propagateActivity property to "true". Activities are actually propagated by setting the activity id (guid) on Trace.CorrelationManager.ActivityId. Can WCF logging and activity propagation be used effectively if you are using log4net or NLog?

My project will be using WCF very heavily. We are currently trying to settle on our logging solution. I think that I have a pretty good understanding of how WCF logging and activity propagation works with System.Diagnostics and TraceSources. I would like to understand better how/if something similar can be achieved with logging platforms like log4net and NLog.

Do they provide some "native" support? It seems a little more likely that they provide some infrastructure so that the activity propagation could be achieved "manually". Maybe something like this:

//Inside client code:
ILog logger = LogManager.GetLogger("client");
Guid oldActivity = Trace.CorrelationManager.ActivityId;
if (oldActivity == Guid.Empty)
{
  Trace.CorrelationManager.ActivityId = Guid.NewGuid();
}

using (LogManager.NDC.Push(Trace.CorrelationManager.ActivityId))
{
  log.Info("Before calling WCF Service");

  wcfService.Method();

  log.Info("After calling WCF Service");
}
Trace.CorrelationManager.ActivityId = oldActivity;

If the log4net/NLog logging format is configured to log the top of the NDC stack, then each message logged by the client (while the activity is in scope) will be "tagged" with the activity id. Assuming that the WCF service is implemented similarly, then all messages logged during the service call will also be logged (albeit, probably in a separate file) and tagged with the same activity id. So, it will be possible to correlate the logging messages in the "service" log file to the corresponding messages in the "client" log.

So, if you use WCF and you have logging, here are some questions:

1. Do you use activity propagation?
2. Do you use TraceSources for logging?
3. Do you use some other logging platform (e.g. log4net, NLog)?
4. If you use another logging platform, how do you do activity propagation?
5. Do you use a mixture of third party logging (log4net/NLog - for most logging) and System.Diagnostics.TraceSource (for WCF service boundary logging)?

What about ServiceTraceViewer? Do you use it? Most examples I have seen show the output being generated by System.Diagnostics via TraceSources and the XmlTraceListener. Can it consume output from log4net, NLog, etc? Does it work "best" with TraceSource-based logging? If so, is it "good enough" to have just a little bit of TraceSource-based logging at the WCF service boundaries (capturing some app context as well as the WCF communication info) for viewing in ServiceTraceViewer? I have used ServiceTraceViewer briefly, just as part of my ongoing WCF learning process.

If you got this far, thanks for reading. Maybe I am overthinking the whole integration of logging, WCF activity propagation, and the ability to view logs in ServiceTraceViewer. It seems like an important consideration in the choice of logging platform and/or logging strategies, but I don't have enough experience with these logging platforms or WCF to know for sure.

Answer 1

Just my nickels worth, I use AOP based logging that I write/maintain myself, but it's like some of the other logging frameworks... Mine is based around decorators, but I can extend it to anything that gets on the callstack.

So where you have something like this:

using (LogManager.NDC.Push(Trace.CorrelationManager.ActivityId)) {
  log.Info("Before calling WCF Service");

  wcfService.Method();

  log.Info("After calling WCF Service");
}
Trace.CorrelationManager.ActivityId = oldActivity;

If you had something like this on the server then mine works in that regard, but my method doesn't work this way for internal logging. Mine is setup to do this:

[LogMethod( CaptureDirection = LoggingDirection.InOut /*Optional*/, CaptureVariables = Yes /*Optional*/ )]
public ClassName MyMethodName(params){
  //magic logging happens here on method entry

  DoSomething();

  //if you need logging here I can't do anything with my AOP system

  DoSomethingElse();


  //magic logging happens here on method exit
}

Additionally, are you looking to have correlated logging between the client and the server? How do you negotiate those two? How can you ensure that one is related to the other?