Introduction
When developing WCF services, we sometimes want to log some entries about our operations. We want to know that our operation has been called and, which parameters had been sent to it. We want to know that our operation has been ended successfully (if it has) and, what is the result. We want to know which errors occurred during our operation and, which parameters had been sent to the operation that cause the error.
Usually, for achieving this goal, I used to write code snippets like this:
WriteToLog(string.Format("MyOperation called. param1={0}, param2={1}", param1, param2));
or, when logging an error, in spite of the main information is the error reason, in order to connect it to the operation and its parameters, I needed to write something like this:
WriteToLog(string.Format("Error occurred in MyOperation.\n Parameters: param1={0},
param2={1}\n Error reason: some reason.", param1, param2));
OK, this isn't such a big deal when you have 2 or 3 native parameters. But, if you have some complex parameters that maybe contain some collections of other complex classes, you can waste a lot of screens of code, only for log prints. Since I got tired of doing that any time I need logs, I decided to write a behavior that simplifies this task.
Background
In this solution, I use a WCF behavior (class that implements: IServiceBehavior, IEndpointBehavior, IContractBehavior or IOperationBehavior). In this behavior, I use parameter-inspector (class that implements IParameterInspector), for getting the details of an operation's invoke and operation's result.
For more information about it, you can read the MSDN topic about Extending Dispatchers.
How Does It Work?
Logging Strategy
Before creating a parameter-inspector that logs operation's invoke and result, we need a logging mechanism to use with. The idea of my solution is to separate the implementation of what to log and when to log, from the implementation of how to handle the log entry. In that way, our behavior is responsible for creating the log entries when they are needed and, the user of this behavior can choose how to handle these log entries. It can be printed to console, written to a file or to a table in a data-base, written to the EventLog or, even sent to another service to handle it. In order to achieve that, we can create an interface that contains a Log method that can be implemented for handling the log entry:
public interface ILoggingStrategy
{
bool Log(LoggingArgument arg);
}
Logging Argument
The Log method gets one parameter of type LoggingArgument:
public class LoggingArgument
{
public LoggingArgument()
{
LogTime = DateTime.Now;
LogType = LoggingType.Information;
}
public DateTime LogTime { get; set; }
public string OperationName { get; set; }
public LoggingType LogType { get; set; }
public LoggingInputsData InputsData { get; set; }
public LoggingOutputsData OutputsData { get; set; }
public LoggingReturnValueData ReturnValueData { get; set; }
public LoggingExceptionData ExceptionData { get; set; }
public LoggingInformationData InformationData { get; set; }
public override string ToString()
{
...
}
}
This argument contains some properties: the log's type, the log's time, the operation's name and, some special parts (properties) for each log type. There is a special type for each special part. The type contains some properties according to its purpose and, an implementation for the ToString method. The idea of it is to let the receiver of the argument to choose between print the default ToString result or, creating his own string according to the given properties, for each special part. For instance, here is the implementation of LoggingReturnValueData:
public class LoggingReturnValueData
{
public object Value { get; set; }
public override string ToString()
{
return ObjectToStringConverter.ConvertToString(Value);
}
}
Converting data to string
The ToString method of each special part uses a class named ObjectToStringConverter. This class uses reflection in order to go over the type of the object and create a string according to it.
For generally converting an object to a string we have the ConvertToString method:
public static string ConvertToString(object value)
{
if (value == null)
{
return "null";
}
Type valueType = value.GetType();
if (valueType == typeof(string) || valueType.IsEnum || IsParsable(valueType))
{
return value.ToString();
}
if (value is Exception)
{
return ConvertExceptionToString(value as Exception);
}
if (value is IEnumerable)
{
return ConvertCollectionToString(value as IEnumerable);
}
if (value is Type)
{
return ConvertTypeToString(value as Type);
}
return ConvertClassToString(value);
}
In this method, we check the type of the object and, call an appropriate method according to it.
In the ConvertExceptionToString method, we create a string that contains the message of the exception and the messages of the inner exceptions recursively.
In the ConvertCollectionToString method, we go over each element of the collection and, call ConvertToString with it.
In the ConvertTypeToString method, we build a string with the type's name and its assembly description.
In the ConvertClassToString method, we go over the properties and data-fields of the class and, call ConvertToString with them.
Logging Behavior
Now, with this logging mechanism we can implement our logging behavior. First, we create a parameter-inspector:
class LoggingParameterInspector : IParameterInspector
{
#region IParameterInspector Members
public void AfterCall(string operationName, object[] outputs,
object returnValue, object correlationState)
{
throw new NotImplementedException();
}
public object BeforeCall(string operationName, object[] inputs)
{
throw new NotImplementedException();
}
#endregion
}
To this parameter-inspector, we add the following properties:
public bool LogBeforeCall { get; set; }
public bool LogAfterCall { get; set; }
#region LoggingStrategy
private ILoggingStrategy _loggingStrategy;
public ILoggingStrategy LoggingStrategy
{
get { return _loggingStrategy ?? (_loggingStrategy = new ConsoleLoggingStrategy()); }
set { _loggingStrategy = value; }
}
#endregion
public Type ServiceType { get; set; }
The LogBeforeCall property determines if the parameter-inspector logs operations' invokes.
The LogAfterCall property determines if the parameter-inspector logs operations' results.
The LoggingStrategy property holds the logging strategy that the parameter-inspector uses. The default strategy is ConsoleLoggingStrategy. This class implements ILoggingStrategy to write the logging entries to the console.
The ServiceType property holds the type of the service. It is used for getting the information about the service's methods.
In the BeforeCall method, we create a LoggingArgument with the method's invoke data and, call the logging strategy with it as the following:
public object BeforeCall(string operationName, object[] inputs)
{
if (ServiceType == null)
{
return null;
}
MethodInfo mi = ServiceType.GetMethod(operationName);
if (mi == null)
{
return null;
}
if (LogBeforeCall)
{
LoggingArgument arg = CreateArgumentForInvokeLog(mi, inputs);
LoggingStrategy.Log(arg);
}
return null;
}
private LoggingArgument CreateArgumentForInvokeLog(MethodInfo mi, object[] inputs)
{
if (mi == null)
{
return null;
}
LoggingArgument res =
new LoggingArgument
{
LogType = LoggingType.Invoke,
OperationName = mi.Name
};
if (inputs != null && inputs.Length > 0)
{
res.InputsData = new LoggingInputsData
{
InputParameters = mi.GetParameters().Where(p => !p.IsOut).ToArray(),
InputValues = inputs
};
}
return res;
}
In the AfterCall method, we create a LoggingArgument with the method's result data and, call the logging strategy with it as the following:
public void AfterCall(string operationName, object[] outputs,
object returnValue, object correlationState)
{
if (!LogAfterCall)
{
return;
}
if (ServiceType == null)
{
return;
}
MethodInfo mi = ServiceType.GetMethod(operationName);
if (mi == null)
{
return;
}
LoggingArgument arg = CreateArgumentForResultLog(mi, outputs, returnValue);
LoggingStrategy.Log(arg);
}
private LoggingArgument CreateArgumentForResultLog
(MethodInfo mi, object[] outputs, object returnValue)
{
if (mi == null)
{
return null;
}
LoggingArgument res =
new LoggingArgument
{
LogType = LoggingType.Result,
OperationName = mi.Name
};
if (outputs != null && outputs.Length > 0)
{
res.OutputsData = new LoggingOutputsData
{
OutputParameters =
mi.GetParameters().Where(p => p.IsOut ||
p.ParameterType.IsByRef).ToArray(),
OutputValues = outputs
};
}
if (mi.ReturnType != typeof(void))
{
res.ReturnValueData = new LoggingReturnValueData
{
Value = returnValue
};
}
return res;
}
Using the LoggingParameterInspector, we create a service behavior that can be used as an attribute for our service:
public class LoggingBehaviorAttribute : Attribute, IServiceBehavior
{
#region IServiceBehavior Members
public void AddBindingParameters(ServiceDescription serviceDescription,
ServiceHostBase serviceHostBase,
Collection<serviceendpoint /> endpoints,
BindingParameterCollection bindingParameters)
{
throw new NotImplementedException();
}
public void ApplyDispatchBehavior(ServiceDescription serviceDescription,
ServiceHostBase serviceHostBase)
{
throw new NotImplementedException();
}
public void Validate(ServiceDescription serviceDescription,
ServiceHostBase serviceHostBase)
{
throw new NotImplementedException();
}
#endregion
}
In the
ApplyDispatchBehavior method, we add the
LoggingParameterInspector to each
DispatchOperation as the following:
public void ApplyDispatchBehavior(ServiceDescription serviceDescription,
ServiceHostBase serviceHostBase)
{
LoggingParameterInspector paramInspector = new LoggingParameterInspector
{
ServiceType = serviceDescription.ServiceType,
LoggingStrategy = GetLoggingStrategy(),
LogAfterCall = LogAfterCall,
LogBeforeCall = LogBeforeCall
};
foreach (ChannelDispatcher chDisp in serviceHostBase.ChannelDispatchers)
{
foreach (EndpointDispatcher epDisp in chDisp.Endpoints)
{
foreach (DispatchOperation op in epDisp.DispatchRuntime.Operations)
{
op.ParameterInspectors.Add(paramInspector);
}
}
}
}
For using this behavior also as an attribute for an operation, we have to implement also IOperationBehavior. In the ApplyDispatchBehavior method, we remove the existing LoggingParameterInspector (there will be a LoggingParameterInspector, if the behavior is used also for the service) and, add a new LoggingParameterInspector according to the properties of the behavior as the following:
public void ApplyDispatchBehavior(OperationDescription operationDescription,
DispatchOperation dispatchOperation)
{
LoggingParameterInspector paramInspector =
dispatchOperation.ParameterInspectors.FirstOrDefault(
pi => pi.GetType() == typeof(LoggingParameterInspector))
as LoggingParameterInspector;
if (paramInspector != null)
{
dispatchOperation.ParameterInspectors.Remove(paramInspector);
}
paramInspector = new LoggingParameterInspector
{
ServiceType = operationDescription.DeclaringContract.ContractType,
LoggingStrategy = GetLoggingStrategy(),
LogAfterCall = LogAfterCall,
LogBeforeCall = LogBeforeCall
};
dispatchOperation.ParameterInspectors.Add(paramInspector);
}
Logging Context
For connecting the operation's details with additional log-prints (error, warning and information logs, that occur during the operation's scope), we need to know the operation's details at each place we want to write a log-print in. In order to achieve that, we can create a class for holding the necessary details for each operation.
First, we need an identifier for the current session. We can use the SessionId of the current OperationContext for that purpose, as the following:
public class LoggingContext
{
protected static string GetCurrentContextId()
{
OperationContext currContext = OperationContext.Current;
if (currContext == null)
{
return null;
}
return currContext.SessionId;
}
}
Using that identifier, we can register the current operations' details of the sessions. For saving the operation's details for each session, we can use a Dictionary of the current session's identifier and the session's operation's details, as the following:
#region Contexts
private static Dictionary<string, LoggingContextDetails> _contexts =
new Dictionary<string, LoggingContextDetails>();
protected static Dictionary<string, LoggingContextDetails> Contexts
{
get { return _contexts; }
}
#endregion
#region Contexts methods
public static bool SetCurrentContextDetails(LoggingContextDetails contextDetails)
{
string currContextId = GetCurrentContextId();
if (currContextId == null)
{
return false;
}
AddContext(currContextId, contextDetails, true);
return true;
}
protected static void AddContext(string id,
LoggingContextDetails contextDetails,
bool replaceIfExist)
{
if (id == null)
{
return;
}
lock (Contexts)
{
if (replaceIfExist && Contexts.ContainsKey(id))
{
Contexts.Remove(id);
}
if (!Contexts.ContainsKey(id) && contextDetails != null)
{
Contexts.Add(id, contextDetails);
}
}
}
public static bool ClearCurrentContextDetails()
{
string currContextId = GetCurrentContextId();
if (currContextId == null)
{
return false;
}
RemoveContext(currContextId);
return true;
}
protected static void RemoveContext(string id)
{
if (id == null)
{
return;
}
lock (Contexts)
{
if (Contexts.ContainsKey(id))
{
Contexts.Remove(id);
}
}
}
#endregion
The operation's details are presented by the type LoggingContextDetails. This type is declared as the following:
public class LoggingContextDetails
{
public MethodInfo MethodDetails { get; set; }
public object[] Inputs { get; set; }
public bool LogErrors { get; set; }
public bool LogWarnings { get; set; }
public bool LogInformation { get; set; }
#region LoggingStrategy
private ILoggingStrategy _loggingStrategy;
public ILoggingStrategy LoggingStrategy
{
get { return _loggingStrategy ??
(_loggingStrategy = new ConsoleLoggingStrategy()); }
set { _loggingStrategy = value; }
}
#endregion
}
We also add a static property for getting the current LoggingContext, as the following:
public static LoggingContext Current
{
get
{
LoggingContext res = new LoggingContext();
string currContextId = GetCurrentContextId();
lock (Contexts)
{
if (Contexts.ContainsKey(currContextId))
{
res.Details = Contexts[currContextId];
}
}
return res;
}
}
#region Details
private LoggingContextDetails _details;
public LoggingContextDetails Details
{
get { return _details ?? (_details = new LoggingContextDetails()); }
protected set { _details = value; }
}
#endregion
For performing the logging, we add a method for creating a basic LoggingArgument according to the details of the LoggingContext:
private LoggingArgument CreateArgumentForCommonLog()
{
LoggingArgument arg = new LoggingArgument();
MethodInfo mi = Details.MethodDetails;
if (mi != null)
{
arg.OperationName = mi.Name;
if (Details.Inputs != null && Details.Inputs.Length > 0)
{
arg.InputsData = new LoggingInputsData
{
InputParameters = mi.GetParameters().Where(p => !p.IsOut).ToArray(),
InputValues = Details.Inputs
};
}
}
return arg;
}
We create a method for logging the wanted log-print:
public bool Log(Exception ex, string text, LoggingType logType)
{
LoggingArgument arg = CreateArgumentForCommonLog();
arg.LogType = logType;
if (ex != null)
{
arg.ExceptionData = new LoggingExceptionData
{
Exception = ex
};
}
if (text != null)
{
arg.InformationData = new LoggingInformationData
{
Text = text
};
}
return Details.LoggingStrategy.Log(arg);
}
and, create methods for each specific log-print:
public bool LogError(Exception ex, string text)
{
if (Details.LogErrors)
{
return Log(ex, text, LoggingType.Error);
}
return false;
}
public bool LogWarning(Exception ex, string text)
{
if (Details.LogWarnings)
{
return Log(ex, text, LoggingType.Warning);
}
return false;
}
public bool LogInformation(string text)
{
if (Details.LogInformation)
{
return Log(null, text, LoggingType.Information);
}
return false;
}
For setting the operation's details for each operation, we can call SetCurrentContextDetails in the BeforeCall method of the LoggingParameterInspector, as the following:
public object BeforeCall(string operationName, object[] inputs)
{
if (ServiceType == null)
{
return null;
}
MethodInfo mi = ServiceType.GetMethod(operationName);
if (mi == null)
{
return null;
}
SetLoggingContext(inputs, mi);
if (LogBeforeCall)
{
LoggingArgument arg = CreateArgumentForInvokeLog(mi, inputs);
LoggingStrategy.Log(arg);
}
return null;
}
private void SetLoggingContext(object[] inputs, MethodInfo mi)
{
LoggingContextDetails lcd = new LoggingContextDetails
{
MethodDetails = mi,
Inputs = inputs,
LoggingStrategy = LoggingStrategy,
LogErrors = LogErrors,
LogWarnings = LogWarnings,
LogInformation = LogInformation
};
LoggingContext.SetCurrentContextDetails(lcd);
}
and, call ClearCurrentContextDetails in the AfterCall method of the LoggingParameterInspector, as the following:
public void AfterCall(string operationName, object[] outputs,
object returnValue, object correlationState)
{
LoggingContext.ClearCurrentContextDetails();
if (!LogAfterCall)
{
return;
}
if (ServiceType == null)
{
return;
}
MethodInfo mi = ServiceType.GetMethod(operationName);
if (mi == null)
{
return;
}
LoggingArgument arg = CreateArgumentForResultLog(mi, outputs, returnValue);
LoggingStrategy.Log(arg);
}
Behavior Configuration
For using the logging behavior in the configuration file, we have to create a configuration element:
public class LoggingBehaviorExtensionElement : BehaviorExtensionElement
{
public override Type BehaviorType
{
get { throw new NotImplementedException(); }
}
protected override object CreateBehavior()
{
throw new NotImplementedException();
}
}
add properties that correspond to the behavior's properties:
[ConfigurationProperty("logBeforeCall", DefaultValue = true)]
public bool LogBeforeCall
{
get { return (bool)this["logBeforeCall"]; }
set { this["logBeforeCall"] = value; }
}
[ConfigurationProperty("logAfterCall", DefaultValue = true)]
public bool LogAfterCall
{
get { return (bool)this["logAfterCall"]; }
set { this["logAfterCall"] = value; }
}
[ConfigurationProperty("logErrors", DefaultValue = true)]
public bool LogErrors
{
get { return (bool)this["logErrors"]; }
set { this["logErrors"] = value; }
}
[ConfigurationProperty("logWarnings", DefaultValue = true)]
public bool LogWarnings
{
get { return (bool)this["logWarnings"]; }
set { this["logWarnings"] = value; }
}
[ConfigurationProperty("logInformation", DefaultValue = true)]
public bool LogInformation
{
get { return (bool)this["logInformation"]; }
set { this["logInformation"] = value; }
}
[ConfigurationProperty("loggingStrategyType")]
public string LoggingStrategyType
{
get { return (string)this["loggingStrategyType"]; }
set { this["loggingStrategyType"] = value; }
}
implement the BehaviorType property to return the type of the behavior:
public override Type BehaviorType
{
get { return typeof(LoggingBehaviorAttribute); }
}
and, implement the CreateBehavior method to return an instance of the behavior:
protected override object CreateBehavior()
{
return new LoggingBehaviorAttribute
{
LogBeforeCall = LogBeforeCall,
LogAfterCall = LogAfterCall,
LogErrors = LogErrors,
LogWarnings = LogWarnings,
LogInformation = LogInformation,
LoggingStrategyType = ConvertStringToType(LoggingStrategyType)
};
}
private Type ConvertStringToType(string strType)
{
if (string.IsNullOrEmpty(strType))
{
return null;
}
Type res = null;
try
{
int firstCommaIndex = strType.IndexOf(",");
if (firstCommaIndex > 0)
{
string typeFullName = strType.Substring(0, firstCommaIndex);
string assemblyFullName = strType.Substring(firstCommaIndex + 1);
Assembly typeAssembly = Assembly.Load(assemblyFullName);
if (typeAssembly != null)
{
res = typeAssembly.GetType(typeFullName);
}
}
}
catch
{
}
return res;
}
How To Use It?
Use the Logging Behavior in the Code
For using the logging behavior in the code, we can put it as an attribute for our service:
[LoggingBehavior]
public class MyService : IMyService
{
public int MyOperation(int myArg, List<family /> families, out string myResult)
{
myResult = "There are " + families.Count + " families.";
return 5;
}
}
When the client calls MyOperation, the log-prints on the service's console can be shown as the following:
For applying different logging settings for a specific operation, we can put the logging behavior as an attribute for the specific operation:
[LoggingBehavior(LogBeforeCall = false)]
public int MySecondOperation(int myArg)
{
return 10;
}
For writing log-prints of errors, warnings and information logs, we can use the LoggingContext class:
[LoggingBehavior]
public class MyService : IMyService
{
public void MyThirdOperation(int i)
{
LoggingContext.Current.LogInformation("In MyThirdOperation");
MyClass c = new MyClass();
c.MyMethod();
}
}
public class MyClass
{
public void MyMethod()
{
LoggingContext.Current.LogInformation("This is a log-print" +
" from a different method in a different class." +
" The operation's details that connected to this log are" +
" the details of the service's operation.");
}
}
Use the Logging Behavior in the Configuration File
For using the logging behavior in the configuration file, we can add a behavior extension with the LoggingBehaviorExtensionElement type:
<system.serviceModel>
<extensions>
<behaviorExtensions>
<add name="loggingBehavior"
type="WcfLogPrints.LoggingBehaviorExtensionElement,
WcfLogPrints, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null"/>
</behaviorExtensions>
</extensions>
...
</system.serviceModel>
and, use it in the service's behavior configuration:
<system.serviceModel>
...
<services>
...
<service name="Example.Services.MySecondService"
behaviorConfiguration="myServiceBehavior">
<endpoint address="net.tcp://localhost:8731/MySecondService"
binding="netTcpBinding"
contract="Example.Contracts.IMySecondService" />
</service>
</services>
<behaviors>
<serviceBehaviors>
<behavior name="myServiceBehavior">
<loggingBehavior logInformation="false" />
</behavior>
</serviceBehaviors>
</behaviors>
...
</system.serviceModel>
Use Different Logging-strategy
For using different logging strategy than the default one, we can implement ILoggingStrategy:
public class FileLoggingStrategy : ILoggingStrategy
{
public bool Log(LoggingArgument arg)
{
if (arg == null)
{
return false;
}
try
{
string logFilePath = FilePath ?? "C:\\Example.txt";
using (FileStream fs = File.Open
(logFilePath, FileMode.Append, FileAccess.Write))
{
using (TextWriter tw = new StreamWriter(fs))
{
tw.Write(arg.ToString());
}
}
}
catch
{
return false;
}
return true;
}
public string FilePath { get; set; }
}
and, set the LoggingStrategyType property on the LoggingBehaviorAttribute attribute:
[LoggingBehavior(LoggingStrategyType = typeof(FileLoggingStrategy))]
public class MyThirdService : IMyThirdService
{
public int MyOperation(int myArg)
{
return 5;
}
}
or, set the
loggingStrategyType attribute in the configuration element:
<behavior name="myServiceBehavior">
<loggingBehavior logInformation="false"
loggingStrategyType="Example.Services.FileLoggingStrategy, Example.Services" />
</behavior>
