WCF Service - Logging Caller Details

Question

I have created a Windows Service (.Net 4.0) that exposes WCF service end points over TCP bindings.

When a service method is called, it will perform several tasks in separate threads. Each class performing the actions has a Log4Net ILog implementation injected in (using dependency injection).

What I would like to do is every log entry to have the IP address of the caller so that I can track a call through or identify which call has errored on the server.

Using log4Net's LogicalThreadContext, I have managed to achieve this for any log message written on the same thread but not for anything on other threads.

Sample code below.

Service Interface:

    [ServiceContract(Namespace = "http://tremac")]
    public interface IBroadcastService
    {
        [OperationContract]
        void PublishMessage(Message message);
    }

Service Implementation:

[ServiceBehavior(InstanceContextMode = InstanceContextMode.Single)]
class BroadcastService: IBroadcastService
{
    private readonly ILog _logger;


    public BroadcastService(ILog logger)
    {
        _logger = logger;
        _logger.Debug("Broadcast Service Initiated");
    }

    public void PublishMessage(Message message)
    {


        var prop =
                OperationContext.Current.IncomingMessageProperties[RemoteEndpointMessageProperty.Name] as
                    RemoteEndpointMessageProperty;
        string ip = prop == null ? "" : prop.Address;

        log4net.LogicalThreadContext.Properties["CallerIp"] = ip;

        try
        {

            _logger.Info("Publishing message from " + message.Sender);
            var sinks = ObjectFactory.GetAllInstances<IMessageWriteRepository>();
            Parallel.ForEach(sinks, x => x.SaveMessage(message));
            _logger.Info("Message published");
        }
        catch (Exception ex)
        {
            _logger.Error("Issue publishing message from " + message.Sender + " on " + ip, ex);
            throw new FaultException("Message was either not published or only partially published. Please contact support");
        }
    }

}

Note the use of Parallel.Foreach where there are several implementations of IMessageWriteRepository being used in parallel. Each of the implementations again has an ILog injected in via Dependency Injection. It appears to be at this point that the context of the caller is lost.

The pattern layout in my Log4Net appender looks like this:

    <conversionPattern value="%date [%-5level] [%thread] [%class] [%property{CallerIp}] %message%newline" />

Finally, the resulting log looks like this:

    2015-06-23 09:49:11,004 [INFO ] [13] [BroadcastService] [127.0.0.1] Publishing message from Graeme on 127.0.0.1
    2015-06-23 09:49:11,073 [INFO ] [13] [RabbitMqMessageWriter] [(null)] Sending message on topic TestTopic
    2015-06-23 09:49:11,073 [INFO ] [15] [DatabaseAndFileshareWriteMessageRepository] [(null)] Saving message body to disk
    2015-06-23 09:49:11,104 [INFO ] [15] [DatabaseAndFileshareWriteMessageRepository] [(null)] Saving message meta to database
    2015-06-23 09:49:11,737 [INFO ] [13] [BroadcastService] [127.0.0.1] Message published

Note the [(null)] where the caller IP should be on the log messages for different threads.

Any suggestions welcome.

Answer 1

Thanks to log4net LogicalThreadContext not working.

The following code will work across threads following upgrade to log4net version 1.12.13.0

log4net.LogicalThreadContext.Properties["CallerIp"] = ip;