This post describes a custom server-side logging solution for WCF services. The basic requirements:

  • Log call details such as:
    • Operation name
    • Operation parameters
    • Caller’s identity
    • Client machine address
    • etc.
  • Ability to exclude specific parameters (e.g. password) from logging.
  • Turn on/off logging at the operation level.
  • No code changes in service methods.

The solution takes advantage of WCF’s extensibility points by injecting an IParameterInspector into the operation’s execution pipeline. This is achieved via a custom IServiceBehavior, configured in web.config with the help of a BehaviorExtensionElement.

Binaries are available on nuget at https://www.nuget.org/packages/OperationLogger.Wcf and the source code is at https://github.com/gilyes/OperationLogger.Wcf.

Usage

After adding a reference to the OperationLogger.Wcf.dll (e.g. via nuget), logging can be enabled with one simple code change and a bit of configuration.

Wiring up logging function

On service initialization (for example in custom ServiceHost’s OnOpening method) setup the OperationLogBehavior.LogAction static function, this will be called with OperationDetails whenever an operation is about to execute:

OperationLogBehavior.LogAction = operationDetails => { /*TODO: log to db/file/whatever*/ }

Configuration

First enable the use of the service behavior by defining the behavior extension element:

<system.serviceModel>
    <extensions>
        <behaviorExtensions>
            <add name="operationLog" 
                 type="OperationLogger.Wcf.OperationLogBehaviorElement, OperationLogger.Wcf" />
        </behaviorExtensions>
        ...

Then add this behavior to the service’s behavior definition:

<behaviors>
    <serviceBehaviors>
        <behavior name="MyServiceBehavior">
            <operationLog>
                <patterns>
                    <add actionPattern=".*" />
                </patterns>
            </operationLog>
            ...

The above configuration example enables logging for all actions. To restrict logging to specific services/actions, add as many pattern entries as needed with the actionPattern set to a regular expression that needs to be matched for logging to be applied. For example:

<operationLog>
    <patterns>
        <add actionPattern=".*IPatientService/FindPatients" />
        <add actionPattern=".*IPatientService/GetPatient" />
        <add actionPattern=".*IExamService/.*" />
    </patterns>
</operationLog>

Parameter logging can be controlled similarly, using the parameterPattern attribute. By default it is turned on for all parameters, but it can be turned off altogether:

<operationLog>
    <patterns>
        <add actionPattern=".*IAuthenticationService/Authenticate" 
             parameterPattern="^$" />
    </patterns>
</operationLog>

Or it could be disabled for specific parameters:

<operationLog>
    <patterns>
        <add actionPattern=".*IAuthenticationService/Authenticate"
             parameterPattern="^((?!password).)*$" />
    </patterns>
</operationLog>

Error handling

Exceptions during logging are swallowed, but the service can get notified of exceptions by setting up the OperationLogBehavior.OnError static function:

OperationLogBehavior.OnError = (e, message) => { /*handle error*/ };

Implementation

Parameter inspector

ParameterInspector implements IParameterInspector. The BeforeCall method is executed before every operation, so that is where we extract operation details from current OperationContext, ServiceSecurityContext, operation inputs, etc then call the log action.

public object BeforeCall(string operationName, object[] inputs)
{
    if (LogAction == null)
    {
        return null;
    }

    try
    {
        var operationContext = OperationContext.Current;
        var securityContext = ServiceSecurityContext.Current;
        var remoteEndpoint = OperationContext.Current.IncomingMessageProperties[RemoteEndpointMessageProperty.Name] 
                                as RemoteEndpointMessageProperty;

        var operationData = 
            new OperationDetails
            {
                OperationName = operationName,
                Action = operationContext.IncomingMessageHeaders.Action,
                ServiceUri = operationContext.Channel.LocalAddress.Uri,
                ClientAddress = remoteEndpoint != null ? remoteEndpoint.Address : "",
                UserName = securityContext != null ? securityContext.PrimaryIdentity.Name : "",
                Identity = securityContext != null ? securityContext.PrimaryIdentity : null,
                IsAnonymous = securityContext == null || securityContext.IsAnonymous
            };

        if (inputs != null)
        {
            // get parameter names
            var parameterInfos = _operationDescription.SyncMethod.GetParameters();

            // add enabled parameters
            int i = 0;
            foreach (var parameterInfo in parameterInfos.Where(x => IsParameterLoggingEnabled(x.Name)))
            {
                operationData.Parameters.Add(parameterInfo.Name, i < inputs.Length ? inputs[i] : null);
                i++;
            }
        }

        LogAction(operationData);
    }
    catch (Exception e)
    {
        // logging failed, try notifying the service
        var onError = OnError;
        if (onError != null)
        {
            onError(e, string.Format("Operation logging failed for '{0}'", operationName));
        }
    }

    return null;
}

Service behavior

OperationLogBehavior implements IServiceBehavior and adds a parameter inspector for all operations that are enabled in the configuration.

public class OperationLogBehavior : IServiceBehavior
{
    public OperationLogBehavior()
    {
        IsEnabledForOperation = operation => true;
        IsParameterLoggingEnabled = (operation, parameterName) => true;
    }

    public static Action<OperationDetails> LogAction { get; set; }
    public static Action<Exception, string> OnError { get; set; }
    public Func<DispatchOperation, bool> IsEnabledForOperation { get; set; }
    public Func<DispatchOperation, string, bool> IsParameterLoggingEnabled { get; set; }

    void IServiceBehavior.AddBindingParameters(ServiceDescription serviceDescription,
                                               ServiceHostBase serviceHostBase,
                                               Collection<ServiceEndpoint> endpoints,
                                               BindingParameterCollection bindingParameters)
    {
    }

    void IServiceBehavior.ApplyDispatchBehavior(ServiceDescription serviceDescription,
                                                ServiceHostBase serviceHostBase)
    {
        // add parameter inspector for all enabled operations in the service
        foreach (var channelDispatcher in serviceHostBase.ChannelDispatchers.OfType<ChannelDispatcher>())
        {
            foreach (var endpointDispatcher in channelDispatcher.Endpoints)
            {
                var endpoint = serviceHostBase.Description.Endpoints.Find(endpointDispatcher.EndpointAddress.Uri);
                foreach (var dispatchOperation in endpointDispatcher.DispatchRuntime.Operations.Where(IsEnabledForOperation))
                {
                    var operationDescription = endpoint != null
                                                   ? GetOperationDescription(endpoint, dispatchOperation)
                                                   : null;
                    AddParameterInspector(dispatchOperation, operationDescription);
                }
            }
        }
    }

    void IServiceBehavior.Validate(ServiceDescription serviceDescription, ServiceHostBase serviceHostBase)
    {
    }

    private static OperationDescription GetOperationDescription(ServiceEndpoint endpoint,
                                                                DispatchOperation dispatchOperation)
    {
        return endpoint.Contract.Operations.Find(dispatchOperation.Name);
    }

    private void AddParameterInspector(DispatchOperation dispatchOperation,
                                       OperationDescription operationDescription)
    {
        var parameterInspector = new ParameterInspector(operationDescription)
                                 {
                                     LogAction = LogAction,
                                     OnError = OnError,
                                     IsParameterLoggingEnabled = parameterName => IsParameterLoggingEnabled(dispatchOperation, parameterName)
                                 };
        dispatchOperation.ParameterInspectors.Add(parameterInspector);
    }
}

Behavior extension element

OperationLogBehaviorElement implements BehaviorExtensionElement and it allows OperationLogBehavior to be configured and associated with services in web.config.

public class OperationLogBehaviorElement : BehaviorExtensionElement
{
    private const string PatternsPropertyName = "patterns";

    public override Type BehaviorType
    {
        get { return typeof (OperationLogBehavior); }
    }

    // Define the <patterns> section to be used in the configuration.
    [ConfigurationProperty(PatternsPropertyName)]
    [ConfigurationCollection(typeof (OperationLogPatternCollection),
        AddItemName = "add", ClearItemsName = "clear", RemoveItemName = "remove")]
    public OperationLogPatternCollection Patterns
    {
        get { return (OperationLogPatternCollection) base[PatternsPropertyName]; }
        set { base[PatternsPropertyName] = value; }
    }

    protected override object CreateBehavior()
    {
        return new OperationLogBehavior
        {
            IsEnabledForOperation = IsEnabledForOperation,
            IsParameterLoggingEnabled = IsParameterLoggingEnabled
        };
    }
    ...
}

OperationLogPatternCollection defines the pattern collection in the configuration by implementing a ConfigurationElementCollection:

public class OperationLogPatternCollection : ConfigurationElementCollection
{
    public override ConfigurationElementCollectionType CollectionType
    {
        get { return ConfigurationElementCollectionType.AddRemoveClearMap; }
    }

    public OperationLogPatternElement this[int index]
    {
        get { return (OperationLogPatternElement) BaseGet(index); }
        set
        {
            if (BaseGet(index) != null)
            {
                BaseRemoveAt(index);
            }
            BaseAdd(index, value);
        }
    }

    public new OperationLogPatternElement this[string Name]
    {
        get { return (OperationLogPatternElement) BaseGet(Name); }
    }

    protected override ConfigurationElement CreateNewElement()
    {
        return new OperationLogPatternElement();
    }

    protected override object GetElementKey(ConfigurationElement element)
    {
        return ((OperationLogPatternElement) element).ActionPattern;
    }

    public int IndexOf(OperationLogPatternElement patternElement)
    {
        return BaseIndexOf(patternElement);
    }

    public void Add(OperationLogPatternElement patternElement)
    {
        BaseAdd(patternElement);
    }

    protected override void BaseAdd(ConfigurationElement element)
    {
        BaseAdd(element, false);
    }

    public void Remove(OperationLogPatternElement patternElement)
    {
        if (BaseIndexOf(patternElement) >= 0)
        {
            BaseRemove(patternElement.ActionPattern);
        }
    }

    public void RemoveAt(int index)
    {
        BaseRemoveAt(index);
    }

    public void Remove(string name)
    {
        BaseRemove(name);
    }

    public void Clear()
    {
        BaseClear();
    }
}

And finally, OperationLogPatternElement is a ConfigurationElement and it defines the actionPattern and parameterPattern item attributes:

public class OperationLogPatternElement : ConfigurationElement
{
    private const string ActionPropertyName = "actionPattern";
    private const string ParameterPatternPropertyName = "parameterPattern";

    [ConfigurationProperty(ActionPropertyName, DefaultValue = null, IsRequired = true, IsKey = false)]
    public string ActionPattern
    {
        get { return (string) this[ActionPropertyName]; }
        set { this[ActionPropertyName] = value; }
    }

    [ConfigurationProperty(ParameterPatternPropertyName, DefaultValue = ".*", IsRequired = false, IsKey = false)]
    public string ParameterPattern
    {
        get { return (string) this[ParameterPatternPropertyName]; }
        set { this[ParameterPatternPropertyName] = value; }
    }