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.

Aria

Have you found any answer re using correlation with NLog? – Grill

Good question. There's a lot of documentation on this subject but apparently very little information :P – Wandawander

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?

Centigram

Yes, we would like to correlate the logging between the client and the server. Let's assume that the client is actually a .NET 4.0 client (not Silverlight because Silverlight does not support Trace.CorrelationManager.*). The client can set Trace.Correlationmanager.ActivityId = <new guid>. If logging captures that value then every logging statement can be tagged with the ActivityId. Now, if we can get that ActivityId to the Server, then logging statements from the server can also tag each logging statement with the ActivityId. If all logging for all clients and servers ... – Aria

... is directed to the same place, let's say a database, then we could query for all logging messages with the same ActivityId, order them by time, and we would be able to see the logging from the server(s) that corresponds to calls from the client. This is available "free" to some extent through WCF ActivityId propogation (as linked in my original question) if you using System.Diagnostics logging/tracing. I am interested in finding out how/if ActivityId propogation integrates with non-System.Diagnostics logging/tracing such as log4net and NLog. – Aria

There are issues using WCF ActivityId propogation with Silverlight clients because Silverlight does not support Trace.CorrelationManager.*, so there is already some work to do to even be able to "start" the Activity in Silverlight. – Aria

@Aria I wasn't even aware of this Trace.CorrelationManager ... How interesting. I'm totally at a loss on how to proceed on that one. Best of luck. – Centigram

You should take a look at it. If you are doing much WCF you might find it useful Essentially, in the calling code you can "start" an activity by setting the ActivityId and, if you have configured WCF correctly in your app.config/web.config file, the ActivityId will be propogated to the WCF service that you call. If the WCF service can process multiple requests simultaneously, then logging the ActivityId with each log message allows the server's log messages to be correlated with the client calls (and any logging it might be doing). – Aria

Answer 2

The article on CodeProject describes how to trace activities with NLog by creating custom renderer and listener, and specify what to log in configuration.

The source code for Nlog   extensions can be found at http://lowleveldesign.codeplex.com/releases/view/96938

Disclaimer: I haven't tried the solution, only planning to use it.

Grill