Improving WCF Service Quality (Part 4 - Logging)

Introduction

We have discussed how to add authentication / authorization in the previous part here. This part explains how I added Logging to WCF services.

Using the Code

We have introduced Aspect Oriented Programming concept to our project in the previous part while we are performing authentication and authorization. Now we are going to use the same concept to log execution details. Basically, we are going to log 3 points. Errors (exceptions specifically), execution times and requests.

To log data, we have to define two classes to hold log data, PerfLog and ErrorLog respectively under the Objects folder of the WCFServices.Shared class library project.

public class PerfLog
{
    public string Path { get; set; }
    public string InData { get; set; }
    public string OutData { get; set; }
    public long ExecutionTime { get; set; }
}

public class ErrorLog
{
    public string Path { get; set; }
    public bool IsException { get; set; }
    public string Messages { get; set; }
    public string ErrorContent { get; set; }
    public string InData { get; set; }
    public DateTime ErrorDate { get; set; }
}

And let's add a new class LogManager under the folder Logging within the WCFService.Utils project and decorate it as follows:

public async void CreateErrorLog(ErrorLog logItem)
{
    // Save data to database
}
public async void CreatePerfLog(PerfLog logItem)
{
    // Save data to database
}

These methods are marked as async for two reasons. First of all, we don't want to spend time on logging to decrease response time. Second, even if logging fails, this is not one of our primary concerns. Failure to save log will cause loss of data, but does not necessarily need to interrupt execution. Remember that our first purpose is to serve client. Fast and accurate. Everything else is secondary to improve quality.

A little explanation on the properties of log records. Path property will hold the name of the Service and Service method called. InData will hold the input parameters fed to the service method, while OutData will hold the response of the Service method. ExecutionTime will hold the time difference between the Service method request and response in milliseconds. IsException property will hold the type of the error. An error might be caused by an Exception thrown, or might be caused by any other factor such as validation. This property will be true if the error is caused by an Exception thrown, false if the error is not caused by an Exception thrown. Messages property holds any information about the error. This can be the Message property of an Exception if an Exception is thrown or concatenated string from an array of string which returns from validation. ErrorContent property is optional but generally it may hold the StackTrace property of an Exception if an Exception is thrown which holds quite sensitive and useful information to fix errors. Finally, ErrorDate property holds the date and time information of the error.

Now it is time to implement the logging process. First to measure the execution time, let's put a Stopwatch to the ServiceMethodAspect class:

private static readonly Stopwatch sw = new Stopwatch();

and start it as soon as the authentication and authorization succeed, instantiate and start it.

if (sw.IsRunning)
    sw.Stop();
sw.Start();

We first check if the stopwatch is already running. This is not really required, but it is a good measure to check all possible events which may cause a failure.

Our OnExit method will be as follows:

public override void OnExit(MethodExecutionArgs args)
{
    PerfLog item = new PerfLog
    {
        Path = $"{args.Method.DeclaringType.FullName}.{args.Method.Name}",
        InData = JsonConvert.SerializeObject(args.Arguments),
        OutData = JsonConvert.SerializeObject(args.ReturnValue),
        ExecutionTime = sw.ElapsedMilliseconds
    };
    sw.Stop();
    LogManager mgr = new LogManager();
    mgr.CreatePerfLog(item);
    base.OnExit(args);
}

and OnException method will be as follows:

public override void OnException(MethodExecutionArgs args)
{
    ErrorLog item = new ErrorLog
    {
        Path = $"{args.Method.DeclaringType.FullName}.{args.Method.Name}",
        InData = JsonConvert.SerializeObject(args.Arguments),
        IsException = true,
        Message = args.Exception.Message,
        ErrorContent = JsonConvert.SerializeObject(args.Exception),
        ErrorDate = DateTime.Now
    };
    sw.Stop();
    LogManager mgr = new LogManager();
    mgr.CreateErrorLog(item);
    args.FlowBehavior = FlowBehavior.Return;
    args.ReturnValue = new BaseResponse
    {
        IsException = true,
        IsSuccess = false,
        Messages = new string[] { args.Exception.Message }
    };
    base.OnException(args);
}

Since we are storing complex objects as string, we need to serialize data. My choice was using JSON, but any serialization process will just do fine. If you also would like to use JSON serialization, you should add NewtonSoft.Json to your project by using NuGet.

If we want to log validation errors as well, we should add the same logging process to our service methods as well. As an example, this will be demonstrated only in the CreatePlayer service method.

[ServiceMethodAspect]
public CreatePlayerResponse CreatePlayer(CreatePlayerRequest request)
{
    try
    {
        CreatePlayerValidator validator = new CreatePlayerValidator();
        ValidationResult valResult = validator.Validate(request);
        if (!valResult.IsValidated)
        {
            ErrorLog item = new ErrorLog
            {
                Path = $"{System.Reflection.MethodBase.GetCurrentMethod().DeclaringType.
                          FullName}.{System.Reflection.MethodBase.GetCurrentMethod().Name}",
                InData = JsonConvert.SerializeObject(request),
                IsException = false,
                Message = "Validation failed",
                ErrorContent = JsonConvert.SerializeObject(valResult.Messages),
                ErrorDate = DateTime.Now
            };
            LogManager mgr = new LogManager();
            mgr.CreateErrorLog(item);
            return new CreatePlayerResponse
            {
                IsException = false,
                IsSuccess = false,
                Messages = valResult.Messages.ToArray()
            };
        }
        return new CreatePlayerResponse
        {
            PlayerId = PlayerRepository.CreateNewPlayer
            (request.Name, request.DateOfBirth, request.Height, request.Weight, request.Club),
            IsException = false,
            IsSuccess = true,
            Messages = new string[] { "Operation successful" }
        };
    }
    catch (Exception ex)
    {
        return new CreatePlayerResponse
        {
            IsException = true,
            IsSuccess = false,
            Messages = new string[] { ex.Message }
        };
    }
}

And, as the most important part, please notice that we have added ServiceMethodAspect attribute prior to the Service method declaration. Without this attribute, all our work will be meaningless, because this attribute is the key to routing the code execution to our aspect methods.

History

• 28^th February, 2022: Initial version