Start / Stop Logging

Another common aspect of logging involves indicating when a service call began processing, as well as when it completed its task. For example: namespace FunctionalLayer.Services { public class ServiceOne { ... public Response CallA(Request request) { Log(LogLevel.Info, "ServiceOne.CallA started"); ... Log(LogLevel.Info, "ServiceOne.CallA completed"); return response; } protected virtual void Log(LogLevel level, string logMessage) {} } }

However, we may remove this type of logging from the Functional Layer and place it in the Logging Layer. To do so, we only need to make CallA() virtual, and have the Logging class wrap it. namespace FunctionalLayer.Services { public class ServiceOne { ... public virtual Response CallA(Request request) { ... return response; } protected virtual void Log(LogLevel level, string logMessage) {} } } namespace Logging.Services { public class ServiceOne : FunctionalLayer.Services.ServiceOne { private ILogger _logger; // writes to a file, or a service ... public override Response CallA(Request request) { Log(LogLevel.Info, "ServiceOne.CallA started"); var response = base.CallA(request); Log(LogLevel.Info, "ServiceOne.CallA completed"); return response; } protected override void Log(LogLevel level, string logMessage) { _logger.WriteLine(level, logMessage); } } }

By placing this type of logging in the Logging Layer, we gain two distinct advantages: 1) we don't have the logging cluttering up the functional code; 2) we can easily add this type of logging after the fact without having to touch the Functional Layer logic (though we may need to make the function virtual).

We can extend this behavior to sub-calls such that we now are given a form of mileposts. These type of mileposts are useful to track how far we have gotten through a process, as well as a rough timer to determine how long each part took to process (assuming that date/time stamps are on each log line). namespace FunctionalLayer.Services { public class ServiceOne { ... public virtual Response CallA(Request request) { var response1 = SubResponse1(...); var response2 = SubResponse2(...); var response3 = SubResponse3(...); ... return response; } protected virtual SubResponse1 SubCall1(...) { ... } protected virtual SubResponse2 SubCall2(...) { ... } protected virtual SubResponse3 SubCall3(...) { ... } protected virtual void Log(LogLevel level, string logMessage) {} } } namespace Logging.Services { public class ServiceOne : FunctionalLayer.Services.ServiceOne { private ILogger _logger; // writes to a file, or a service ... public override Response CallA(Request request) { _logger.WriteLine(LogLevel.Info, "CallA Started"); var results = base.CallA(request); _logger.WriteLine(LogLevel.Info, "CallA Completed"); return results; } protected override SubResponse1 SubCall1(...) { var results = base.SubCall1(...); _logger.WriteLine(LogLevel.Info, "SubCall1 Completed"); return results; } protected override SubResponse2 SubCall2(...) { var results = base.SubCall2(...); _logger.WriteLine(LogLevel.Info, "SubCall2 Completed"); return results; } protected override SubResponse3 SubCall3(...) { var results = base.SubCall3(...); _logger.WriteLine(LogLevel.Info, "SubCall3 Completed"); return results; } protected override void Log(LogLevel level, string logMessage) { _logger.WriteLine(level, logMessage); } } }

It is very important to keep exception handling in mind when using Start Stop Logging to track a call. If a thrown exception is able to reach the Logging Layer, then the "Complete" lines as shown above may not be logged at all. The fact the lines are missing may still be used as a negative verification, as their lack of presence lets you infer where the code stopped processing the call.

In this type of situation, it is very important that the topmost function that contains the "Start" and "Completed" lines captures the exception and handles the error if at all feasible. By doing so, we are able to retain a clear beginning and ending of the over all service call. If we are unable to completely handle the exception, then we will have situations where the logging shows a service call was started, and then possibly nothing afterwards.

Next: Request / Response Logging