Request / Response Logging

An extension of the Start / Stop Logging is the Request / Response Logging. In this case, instead of merely logging the fact that the service call was started, and then completed, we log the request that starts the service call, and the response that will be returned.

namespace FunctionalLayer.Objects { public class Request { public string RequestId { get; set; } public string Account { get; set; } public string ProductCode { get; set; } public int Quantity { get; set; } } public class Response { public ResultCode Result { get; set; } public int Quantity { get; set; } // actual amount ordered public decimal Cost { get; set; } public string ErrorMessage { get; set; } // only has a value if there is an error } public class ServiceOne { ... public virtual Response CallA(Request request) { ... return response; } protected virtual void Log(LogLevel level, string logMessage) {} } } namespace LoggingLayer.Objects { public class ServiceOne : FunctionalLayer.Objects.ServiceOne { private ILogger _logger; ... public override Response CallA(Request request) { Log(LogLevel.Info, string.Format("CallA=Request RequestId={0} Account={1} ProductCode={2} Quantity={3}", request.RequestId, request.Account, request.ProductCode, request.Quantity)); var response = base.CallA(request); string message = response.ErrorMessage != null && response.ErrorMessage.Length > 0 ? string.Format(" ErrorMessage=\"{0}\", response.Message) : string.Empty; Log(LogLevel.Info, string.Format( "CallA=Response RequestId={0} Account={1} Result={2} Quantity={3} Cost={4}{5}", request.RequestId, request.Account, response.Result, response.Quantity, response.Cost, message)); return response; } protected override void Log(LogLevel level, string logMessage) { _logger.WriteLine(level, logMessage); } } }

The logging from this example provides us with a lot of information that can be easily searched and analyzed.

CallA=Request|Response lets us clearly determine which service call generated the logged line, as well as if it was the request line or the response line.

RequestID allows us to easily associate a specific request line with a specific response.

Account lets us know the specific account that made the service call.

ProductCode tells us what product the customer was interested in.

Quantity tells us how much the customer ordered, or received.

Result indicates if the call was successful or not.

Cost tells us how much the order cost.

ErrorMessage tells us what the error was, if one occurred. Note that the expected result in this example is that there will be no error message, so the ErrorMessage will not display anything if there is not one.

What can we get from this info? A lot!

If the logging search interface allows us to associate multiple log lines, then we can make even more complicated searches, by using the RequestID to associate the request line with the response line:

We can further extend the use of the RequestID by making sure that any external service that is called is passed the same RequestID. That way, any logging generated by the sub-calls has the same RequestID, and thus we can easily determine that the logging generated by the two services are related.

Next: Metrics