Web API allows you to plug in extensive logging mechanism through the ITraceWriter service. This will log all important events in the pipeline - such as selection of the controller, action, parameter binding and so on - all of which are extremely important in debugging all kinds of issues.
However, any existing instance of an ITraceWriter would log all of the information aside - into a log file, trace, database. But what if you wanted all the trace information produced while the given request was being processed, to be returned together with the server response?
Let’s have a look.
Request.Properties for per-request storage π
While Web API doesn’t use any magical context object like we are used to in ASP.NET with HttpContext.Current, it uses the next best thing - a “god-like” HttpRequestMessage, which is not static but an instance of which is created for each HTTP request and then passed around between almost all important activities in the processing pipeline. This allows us to use it as a per-request storage - and the Properties dictionary on it is perfect just for that purpose.
Writing a custom per-request ITraceWriter π
Let’s create an implementation of an ITraceWriter, which, instead of logging everything to some centralized target, would instead write all of the trace information to the current Request.Properties dictionary.
At the end of the execution pipeline, with the help of a custom MessageHandler, we could pick up this information and attach to the outgoing HttpResponseMessage.
public class PerRequestTraceWriter : ITraceWriter
{
private readonly ITraceWriter _innerWriter;
public PerRequestTraceWriter() : this(null)
{}
public PerRequestTraceWriter(ITraceWriter innerWriter)
{
_innerWriter = innerWriter;
}
public void Trace(HttpRequestMessage request, string category, TraceLevel level, Action<TraceRecord> traceAction)
{
if (request != null)
{
var traceQueryString = request.GetQueryString("trace");
bool shouldTrace;
if (traceQueryString != null && Boolean.TryParse(traceQueryString, out shouldTrace) && shouldTrace)
{
object perRequestTrace;
if (!request.Properties.TryGetValue("perRequestTrace", out perRequestTrace))
{
perRequestTrace = new List<string>();
request.Properties["perRequestTrace"] = perRequestTrace;
}
var record = new TraceRecord(request, category, level);
traceAction(record);
(perRequestTrace as List<string>).Add(Log(record));
}
}
if (_innerWriter != null)
{
_innerWriter.Trace(request, category, level, traceAction);
}
}
private static string Log(TraceRecord record)
{
var message = new StringBuilder();
if (record.Request != null)
{
if (record.Request.Method != null)
message.Append(record.Request.Method);
if (record.Request.RequestUri != null)
message.Append(" ").Append(record.Request.RequestUri.AbsoluteUri);
}
if (!string.IsNullOrWhiteSpace(record.Category))
message.Append(" ").Append(record.Category);
if (!string.IsNullOrWhiteSpace(record.Operator))
message.Append(" ").Append(record.Operator).Append(" ").Append(record.Operation);
if (!string.IsNullOrWhiteSpace(record.Message))
message.Append(" ").Append(record.Message);
if (record.Exception != null && !string.IsNullOrWhiteSpace(record.Exception.GetBaseException().Message))
message.Append(" ").Append(record.Exception.GetBaseException().Message);
return string.Format("{0} {1}", record.Level, message);
}
}
Despite a deceiving complexity, the trace writer is really simple. The core activity happens inside the Trace method - into which Web API will pass the current instance of the HttpRequestMessage. Since in some cases it would be null, we’d only go into our per-request tracing path when it isn’t. I used Rick’s helper method GetQueryString to check the value of the “trace” querystring - if it’s set to true, we want to use our tracer, otherwise we won’t.
The next step is to try to grab a List
Finally, notice that we allow the tracer to have inner tracer - this allows you to still plug in and use something like an NLog or log4net tracer in addition to the request-bound tracer; this is a neat trick we have to do, since Web API only allows to have a single ItraceWriter registered.
Producing a relevant HttpResponseMessage π
The next step is to plugin a custom message handler at the end of the pipeline, and extract whatever has been logged from the HttpRequestMessage.
public class TraceHelperHandler : DelegatingHandler
{
protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
CancellationToken cancellationToken)
{
var response = await base.SendAsync(request, cancellationToken);
object perRequestTrace;
if (request.Properties.TryGetValue("perRequestTrace", out perRequestTrace))
{
var trace = perRequestTrace as List<string>;
if (trace != null)
{
for (var i = 0; i < trace.Count; i++) { response.Headers.Add("Trace" + i.ToString("D2"), trace[i]); } } } return response; } }
Of course the real issue is how to store this trace information in the outgoing response message? One idea - as seen above, is to dump every line from trace into the headers. This is not super elegant, but works very well because it is completely non-invasive - you can switch the tracing for the request on and not break any client at all, since all additional info is packaged into the headers.
By the way, we are free to use any header names we want since the “x-” prefix for custom headers is long deprecated.
Instead of putting each tracer line into a new header, you could also package everything into a single header, since headers can contain arrays - but some devices/browsers limit the size of individual header. Usually, most tools do not format it in the best way too.
The result looks like this:
There are a few other ways of approaching this, but in general it requires breaking the client for the response containing trace info. You could create a custom JsonMediaTypeFormatter and override the WriteToStreamAsync. Then, instead of writing the object passed in, you would write something like this:
public class TraceInfo
{
public IEnumerable<string> Trace {get; set;}
public object Data {get; set;}
}
But this is hardly optimal since now the client is broken, as the response shifts from the main object to the Data property. This approach would also work only for JSON.
If you are not worried with breaking the client temporarily (for the traced responses), one other alternative, and this is way more elegant, is to produce a mixed/multipart response. So effectively sent down a response packaging the original response, plus a second response with the trace information. This is shown in the next snippet.
if (trace != null)
{
var traceResponse = new HttpResponseMessage(HttpStatusCode.OK)
{
Content = new ObjectContent<List<string>>(trace, new JsonMediaTypeFormatter())
};
var combinedResponse = new HttpResponseMessage(HttpStatusCode.OK)
{
Content = new MultipartContent("mixed")
{
new HttpMessageContent(traceResponse),
new HttpMessageContent(response)
}
};
return combinedResponse;
}
The result looks like this:
